This is an automated email from the ASF dual-hosted git repository. daim pushed a commit to branch OAK-10741 in repository https://gitbox.apache.org/repos/asf/jackrabbit-oak.git
commit ba003d64de36bd90b07ffbc752342ccdeb551ebe Author: Rishabh Kumar <[email protected]> AuthorDate: Thu Apr 4 18:57:26 2024 +0530 OAK-10741 : added separate logger for detailed gc --- .../jackrabbit/oak/run/RevisionsCommand.java | 3 +- .../plugins/document/VersionGCRecommendations.java | 23 +-- .../plugins/document/VersionGarbageCollector.java | 157 ++++++++++++--------- 3 files changed, 101 insertions(+), 82 deletions(-) diff --git a/oak-run/src/main/java/org/apache/jackrabbit/oak/run/RevisionsCommand.java b/oak-run/src/main/java/org/apache/jackrabbit/oak/run/RevisionsCommand.java index 465fb89eee..d2c94ccb43 100644 --- a/oak-run/src/main/java/org/apache/jackrabbit/oak/run/RevisionsCommand.java +++ b/oak-run/src/main/java/org/apache/jackrabbit/oak/run/RevisionsCommand.java @@ -95,7 +95,8 @@ public class RevisionsCommand implements Command { private static final List<String> LOGGER_NAMES = of( "org.apache.jackrabbit.oak.plugins.document.VersionGarbageCollector", - "org.apache.jackrabbit.oak.plugins.document.NodeDocumentSweeper" + "org.apache.jackrabbit.oak.plugins.document.NodeDocumentSweeper", + "org.apache.jackrabbit.oak.plugins.document.VersionGarbageCollector.detailedGC" ); private static class RevisionsOptions extends Utils.NodeStoreOptions { diff --git a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/VersionGCRecommendations.java b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/VersionGCRecommendations.java index 0115b07d76..a428779fa8 100644 --- a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/VersionGCRecommendations.java +++ b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/VersionGCRecommendations.java @@ -141,17 +141,6 @@ public class VersionGCRecommendations { detailedGCTimestamp = (long) settings.get(SETTINGS_COLLECTION_DETAILED_GC_TIMESTAMP_PROP); oldestModifiedDocId = (String) settings.get(SETTINGS_COLLECTION_DETAILED_GC_DOCUMENT_ID_PROP); - if (detailedGCTimestamp == 0) { - // it will only happen for the very first time, we run this detailedGC - log.info("No detailedGCTimestamp found, querying for the oldest modified candidate"); - vgc.getOldestModifiedDoc(clock).ifPresentOrElse( - d -> oldestModifiedDocTimeStamp.set(SECONDS.toMillis(ofNullable(d.getModified()).orElse(0L))), - () -> oldestModifiedDocTimeStamp.set(0L)); - oldestModifiedDocId = MIN_ID_VALUE; - log.info("detailedGCTimestamp found: {}", timestampToString(oldestModifiedDocTimeStamp.get())); - } else { - oldestModifiedDocTimeStamp.set(detailedGCTimestamp); - } detailedGCDryRunTimestamp = (long) settings.get(SETTINGS_COLLECTION_DETAILED_GC_DRY_RUN_TIMESTAMP_PROP); oldestModifiedDryRunDocId = (String) settings.get(SETTINGS_COLLECTION_DETAILED_GC_DRY_RUN_DOCUMENT_ID_PROP); @@ -167,6 +156,18 @@ public class VersionGCRecommendations { } else { oldestModifiedDryRunDocTimeStamp.set(detailedGCDryRunTimestamp); } + } else { + if (detailedGCTimestamp == 0) { + // it will only happen for the very first time, we run this detailedGC + log.info("No detailedGCTimestamp found, querying for the oldest modified candidate"); + vgc.getOldestModifiedDoc(clock).ifPresentOrElse( + d -> oldestModifiedDocTimeStamp.set(SECONDS.toMillis(ofNullable(d.getModified()).orElse(0L))), + () -> oldestModifiedDocTimeStamp.set(0L)); + oldestModifiedDocId = MIN_ID_VALUE; + log.info("detailedGCTimestamp found: {}", timestampToString(oldestModifiedDocTimeStamp.get())); + } else { + oldestModifiedDocTimeStamp.set(detailedGCTimestamp); + } } TimeInterval scopeDetailedGC = new TimeInterval(isDetailedGCDryRun ? oldestModifiedDryRunDocTimeStamp.get() : 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 8aece8136d..7aeb54fc0c 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 @@ -50,6 +50,7 @@ import org.apache.jackrabbit.guava.common.collect.Maps; import org.apache.jackrabbit.guava.common.collect.Sets; import org.apache.jackrabbit.oak.commons.sort.StringSort; +import org.apache.jackrabbit.oak.plugins.document.NodeDocument.SplitDocType; import org.apache.jackrabbit.oak.plugins.document.UpdateOp.Key; import org.apache.jackrabbit.oak.plugins.document.UpdateOp.Operation; import org.apache.jackrabbit.oak.plugins.document.UpdateOp.Operation.Type; @@ -71,6 +72,7 @@ import org.slf4j.LoggerFactory; import static java.lang.Math.round; import static java.lang.String.join; import static java.util.Collections.emptySet; +import static java.util.Objects.nonNull; import static java.util.Objects.requireNonNull; import static java.util.Optional.ofNullable; import static java.util.concurrent.TimeUnit.MILLISECONDS; @@ -88,8 +90,12 @@ import static org.apache.jackrabbit.guava.common.util.concurrent.Atomics.newRefe import static java.util.concurrent.TimeUnit.MICROSECONDS; import static org.apache.jackrabbit.oak.plugins.document.Collection.NODES; import static org.apache.jackrabbit.oak.plugins.document.Collection.SETTINGS; +import static org.apache.jackrabbit.oak.plugins.document.NodeDocument.BRANCH_COMMITS; +import static org.apache.jackrabbit.oak.plugins.document.NodeDocument.COLLISIONS; +import static org.apache.jackrabbit.oak.plugins.document.NodeDocument.COMMIT_ROOT; import static org.apache.jackrabbit.oak.plugins.document.NodeDocument.MIN_ID_VALUE; import static org.apache.jackrabbit.oak.plugins.document.NodeDocument.MODIFIED_IN_SECS; +import static org.apache.jackrabbit.oak.plugins.document.NodeDocument.REVISIONS; 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; @@ -108,11 +114,12 @@ public class VersionGarbageCollector { private static final String STATUS_IDLE = "IDLE"; private static final String STATUS_INITIALIZING = "INITIALIZING"; private static final Logger log = LoggerFactory.getLogger(VersionGarbageCollector.class); + private static final Logger DETAILED_GC_LOG = LoggerFactory.getLogger(VersionGarbageCollector.class.getName() + ".detailedGC"); /** * Split document types which can be safely garbage collected */ - private static final Set<NodeDocument.SplitDocType> GC_TYPES = EnumSet.of( + private static final Set<SplitDocType> GC_TYPES = EnumSet.of( DEFAULT_LEAF, COMMIT_ROOT_ONLY, DEFAULT_NO_BRANCH); /** @@ -187,7 +194,7 @@ public class VersionGarbageCollector { this.isDetailedGCDryRun = isDetailedGCDryRun; this.embeddedVerification = embeddedVerification; this.options = new VersionGCOptions(); - log.info("<init> VersionGarbageCollector created with revisionDetailedGcType = {}", revisionDetailedGcType); + DETAILED_GC_LOG.info("<init> VersionGarbageCollector created with revisionDetailedGcType = {}", revisionDetailedGcType); } void setStatisticsProvider(StatisticsProvider provider) { @@ -776,6 +783,9 @@ public class VersionGarbageCollector { // set foundDoc to false to allow exiting the while loop foundDoc = false; lastDoc = null; + if (DETAILED_GC_LOG.isDebugEnabled()) { + DETAILED_GC_LOG.debug("Fetching docs from [{}] to [{}] with Id starting from [{}]", timestampToString(fromModifiedMs), timestampToString(toModifiedMs), fromId); + } Iterable<NodeDocument> itr = versionStore.getModifiedDocs(fromModifiedMs, toModifiedMs, DETAILED_GC_BATCH_SIZE, fromId); try { for (NodeDocument doc : itr) { @@ -783,7 +793,7 @@ public class VersionGarbageCollector { // continue with GC? if (cancel.get()) { foundDoc = false; // to exit while loop as well - log.info("Received GC cancel call. Terminating the GC Operation."); + DETAILED_GC_LOG.info("Received GC cancel call. Terminating the GC Operation."); break; } docsTraversed++; @@ -806,7 +816,7 @@ public class VersionGarbageCollector { } else if (SECONDS.toMillis(modified) < fromModifiedMs) { monitor.warn( "collectDetailedGarbage : document has older _modified than query boundary : {} (from: {}, to: {})", - modified, fromModifiedMs, toModifiedMs); + modified, timestampToString(fromModifiedMs), timestampToString(toModifiedMs)); } } // now remove the garbage in one go, if any @@ -823,6 +833,9 @@ public class VersionGarbageCollector { phases.stats.oldestModifiedDocTimeStamp = fromModifiedMs; phases.stats.oldestModifiedDocId = fromId; oldModifiedMs = fromModifiedMs; + if (DETAILED_GC_LOG.isDebugEnabled()) { + DETAILED_GC_LOG.debug("Fetched docs till [{}] with Id [{}]", timestampToString(fromModifiedMs), fromId); + } } // if we didn't find any document i.e. either we are already at last document // of current timeStamp or there is no document for this timeStamp @@ -1048,8 +1061,9 @@ public class VersionGarbageCollector { updateOpList.add(op); } } - if (log.isDebugEnabled()) { - log.debug("UpdateOp for {} is {}", doc.getId(), op); + if (DETAILED_GC_LOG.isDebugEnabled() && op.hasChanges()) { + // only log in case of changes & debug level enabled + DETAILED_GC_LOG.debug("UpdateOp for {} is {}", doc.getId(), op); } } @@ -1084,6 +1098,9 @@ public class VersionGarbageCollector { // update the deleted properties count Map to calculate the total no. of deleted properties deletedInternalPropsCountMap.merge(doc.getId(), deletedSystemPropsCount, Integer::sum); + if (DETAILED_GC_LOG.isDebugEnabled()) { + DETAILED_GC_LOG.debug("Collected {} internal prop revs for document {} in {} mode", deletedSystemPropsCount, doc.getId(), revisionDetailedGcType); + } } } @@ -1130,6 +1147,10 @@ public class VersionGarbageCollector { orphanOrDeletedRemovalMap.put(doc.getId(), doc.getModified()); orphanOrDeletedRemovalPathMap.put(doc.getId(), doc.getPath()); + if (DETAILED_GC_LOG.isDebugEnabled()) { + DETAILED_GC_LOG.debug("Collected {} deleted or orphaned node", doc.getId()); + } + phases.stop(GCPhase.DETAILED_GC_COLLECT_ORPHAN_NODES); return true; @@ -1165,8 +1186,8 @@ public class VersionGarbageCollector { deletedPropsCountMap.put(doc.getId(), deletedPropsCount); - if (log.isDebugEnabled()) { - log.debug("Collected {} deleted properties for document {}", deletedPropsCount, doc.getId()); + if (DETAILED_GC_LOG.isDebugEnabled() && deletedPropsCount > 0) { + DETAILED_GC_LOG.debug("Collected {} deleted properties for document {}", deletedPropsCount, doc.getId()); } phases.stop(GCPhase.DETAILED_GC_COLLECT_PROPS); } @@ -1204,8 +1225,8 @@ public class VersionGarbageCollector { olderUnmergedBranchCommits.forEach(bcRevision -> removeUnmergedBCRevision(bcRevision, doc, updateOp)); deletedUnmergedBCSet.addAll(olderUnmergedBranchCommits); - if (log.isDebugEnabled()) { - log.debug("Collected {} unmerged branch commits for document {}", olderUnmergedBranchCommits.size(), doc.getId()); + if (DETAILED_GC_LOG.isDebugEnabled()) { + DETAILED_GC_LOG.debug("Collected {} unmerged branch commits for document {}", olderUnmergedBranchCommits.size(), doc.getId()); } // now for any of the handled system properties (the normal properties would @@ -1250,7 +1271,7 @@ public class VersionGarbageCollector { return m.size() == value; } else { // unexpected and would likely indicate a bug, hence log.error - log.error("collectUnmergedBranchCommitDocument: property without sub-document as expected. " + + DETAILED_GC_LOG.error("collectUnmergedBranchCommitDocument: property without sub-document as expected. " + "id={}, prop={}", doc.getId(), prop); return false; } @@ -1357,7 +1378,7 @@ public class VersionGarbageCollector { internalRevEntriesCount++; NodeDocument.removeRevision(updateOp, unmergedBCRevision); } - if (doc.getLocalMap(NodeDocument.COLLISIONS).containsKey(unmergedBCRevision)) { + if (doc.getLocalMap(COLLISIONS).containsKey(unmergedBCRevision)) { internalRevEntriesCount++; NodeDocument.removeCollision(updateOp, unmergedBCRevision); } @@ -1383,10 +1404,14 @@ public class VersionGarbageCollector { deletedPropRevsCountMap.merge(doc.getId(), revEntriesCount, Integer::sum); } + if (DETAILED_GC_LOG.isDebugEnabled()) { + DETAILED_GC_LOG.debug("Collected {} prop revs, {} internal prop revs for document {} in {} mode", deletedPropRevsCountMap.get(doc.getId()), deletedInternalPropRevsCountMap.get(doc.getId()), doc.getId(), revisionDetailedGcType); + } + } - private void collectRevisionsOlderThan24hAndBetweenCheckpoints(final NodeDocument doc, - final GCPhases phases, final UpdateOp updateOp) { + private void collectRevisionsOlderThan24hAndBetweenCheckpoints(final NodeDocument doc, final GCPhases phases, + final UpdateOp updateOp) { if (phases.start(GCPhase.DETAILED_GC_COLLECT_OLD_REVS)){ NodeDocumentRevisionCleaner cleaner = new NodeDocumentRevisionCleaner(nodeStore, doc); cleaner.collectOldRevisions(updateOp); @@ -1411,11 +1436,11 @@ public class VersionGarbageCollector { } final Set<Revision> allKeepRevs = new HashSet<>(); // phase A : collectUnusedUserPropertyRevisions - int deletedTotalRevsCount = collectUnusedUserPropertyRevisions(doc, phases, updateOp, traversedMainNode, allKeepRevs); + int deletedTotalRevsCount = collectUnusedUserPropertyRevisions(doc, updateOp, traversedMainNode, allKeepRevs); int deletedUserRevsCount = deletedTotalRevsCount; // phase B : collectUnusedInternalPropertyRevisions if (!ignoreInternalProperties) { - deletedTotalRevsCount = collectUnusedInternalPropertyRevisions(doc, phases, updateOp, traversedMainNode, allKeepRevs, deletedTotalRevsCount); + deletedTotalRevsCount = collectUnusedInternalPropertyRevisions(doc, updateOp, allKeepRevs, deletedTotalRevsCount); } // then some accounting... @@ -1426,13 +1451,16 @@ public class VersionGarbageCollector { if (deletedInternalRevsCount != 0) { deletedInternalPropRevsCountMap.merge(doc.getId(), deletedInternalRevsCount, Integer::sum); } + + if (DETAILED_GC_LOG.isDebugEnabled()) { + DETAILED_GC_LOG.debug("Collected {} prop revs, {} internal prop revs for document {} in {} mode", deletedPropRevsCountMap.get(doc.getId()), deletedInternalPropRevsCountMap.get(doc.getId()), doc.getId(), revisionDetailedGcType); + } + phases.stop(GCPhase.DETAILED_GC_COLLECT_OLD_REVS); } - private int collectUnusedUserPropertyRevisions(final NodeDocument doc, - final GCPhases phases, final UpdateOp updateOp, - final DocumentNodeState traversedMainNode, - final Set<Revision> allKeepRevs) { + private int collectUnusedUserPropertyRevisions(final NodeDocument doc, final UpdateOp updateOp, + final DocumentNodeState traversedMainNode, final Set<Revision> allKeepRevs) { // phase 1 : non bundled nodes only int deletedRevsCount = stream( traversedMainNode.getProperties().spliterator(), false) @@ -1462,13 +1490,13 @@ public class VersionGarbageCollector { final String unbundledPath = traversedMainNode.getPath().toString() + "/" + unbundledSubtreeName; final DocumentNodeState traversedNode = bundledNodeStates.get(Path.fromString(unbundledPath)); if (traversedNode == null) { - log.error("collectUnusedPropertyRevisions : could not find traversed node for bundled key {} unbundledPath {} in doc {}", + DETAILED_GC_LOG.error("collectUnusedPropertyRevisions : could not find traversed node for bundled key {} unbundledPath {} in doc {}", propName, unbundledPath, doc.getId()); continue; } final PropertyState traversedProperty = traversedNode.getProperty(unbundledPropName); if (traversedProperty == null) { - log.error("collectUnusedPropertyRevisions : could not get property {} from traversed node {}", + DETAILED_GC_LOG.error("collectUnusedPropertyRevisions : could not get property {} from traversed node {}", unbundledPropName, traversedNode.getPath()); continue; } @@ -1486,11 +1514,8 @@ public class VersionGarbageCollector { return deletedRevsCount; } - private int collectUnusedInternalPropertyRevisions(final NodeDocument doc, - final GCPhases phases, final UpdateOp updateOp, - final DocumentNodeState traversedMainNode, - final Set<Revision> toKeepUserPropRevs, - int deletedRevsCount) { + private int collectUnusedInternalPropertyRevisions(final NodeDocument doc, final UpdateOp updateOp, + final Set<Revision> toKeepUserPropRevs, int deletedRevsCount) { boolean hasUnmergedBranchCommits = doc.getLocalBranchCommits().stream() .anyMatch(r -> !isCommitted(nodeStore.getCommitValue(r, doc))); if (deletedRevsCount == 0 && !hasUnmergedBranchCommits) { @@ -1500,8 +1525,8 @@ public class VersionGarbageCollector { Set<Revision> allRequiredRevs = new HashSet<>(toKeepUserPropRevs); // "_collisions" deletedRevsCount += getDeletedRevsCount( - doc.getLocalMap(NodeDocument.COLLISIONS).keySet(), updateOp, - allRequiredRevs, NodeDocument.COLLISIONS, + doc.getLocalMap(COLLISIONS).keySet(), updateOp, + allRequiredRevs, COLLISIONS, NodeDocument::removeCollision); // "_revisions" for (Entry<Revision, String> e : doc.getLocalRevisions().entrySet()) { @@ -1568,7 +1593,7 @@ public class VersionGarbageCollector { // non root and bc : can remove, as non root bc cannot be referenced by child } } - Operation has = updateOp.getChanges().get(new Key(NodeDocument.REVISIONS, revision)); + Operation has = updateOp.getChanges().get(new Key(REVISIONS, revision)); if (has != null) { // then skip continue; @@ -1578,12 +1603,10 @@ public class VersionGarbageCollector { } // "_commitRoot" deletedRevsCount += getDeletedRevsCount(doc.getLocalCommitRoot().keySet(), - updateOp, allRequiredRevs, NodeDocument.COMMIT_ROOT, - NodeDocument::removeCommitRoot); + updateOp, allRequiredRevs, COMMIT_ROOT, NodeDocument::removeCommitRoot); // "_bc" deletedRevsCount += getDeletedRevsCount(doc.getLocalBranchCommits(), updateOp, - allRequiredRevs, NodeDocument.BRANCH_COMMITS, - NodeDocument::removeBranchCommit); + allRequiredRevs, BRANCH_COMMITS, NodeDocument::removeBranchCommit); return deletedRevsCount; } @@ -1613,8 +1636,8 @@ public class VersionGarbageCollector { // could be due to node not existing or current value being in a split // doc - while the former is unexpected, the latter might happen. // in both cases let's skip this property - if (log.isDebugEnabled()) { - log.debug("removeUnusedPropertyEntries : no visible revision for property {} in doc {}", + if (DETAILED_GC_LOG.isDebugEnabled()) { + DETAILED_GC_LOG.debug("removeUnusedPropertyEntries : no visible revision for property {} in doc {}", propertyKey, doc.getId()); } return 0; @@ -1624,7 +1647,7 @@ public class VersionGarbageCollector { final SortedMap<Revision, String> localMap = doc.getLocalMap(propertyKey); if (!localMap.containsKey(keepCommitRev)) { // this is unexpected - log and skip this property - log.error("removeUnusedPropertyEntries : revision {} for property {} not found in doc {}", + DETAILED_GC_LOG.error("removeUnusedPropertyEntries : revision {} for property {} not found in doc {}", keepCommitRev, propertyKey, doc.getId()); return 0; } @@ -1637,8 +1660,8 @@ public class VersionGarbageCollector { // via collectUnmergedBranchCommits. Checking for that next. Operation c = updateOp.getChanges().get(new Key(propertyKey, localRev)); if (c == null) { - if (log.isTraceEnabled()) { - log.trace("removeUnusedPropertyEntries : removing property key {} with revision {} from doc {}", + if (DETAILED_GC_LOG.isTraceEnabled()) { + DETAILED_GC_LOG.trace("removeUnusedPropertyEntries : removing property key {} with revision {} from doc {}", propertyKey, localRev, doc.getId()); } removeRevision.accept(localRev); @@ -1664,21 +1687,22 @@ public class VersionGarbageCollector { public void removeGarbage(final VersionGCStats stats) { if (updateOpList.isEmpty() && orphanOrDeletedRemovalMap.isEmpty()) { - if (log.isDebugEnabled() || isDetailedGCDryRun) { - log.debug("Skipping removal of detailed garbage, cause no garbage detected"); + if (DETAILED_GC_LOG.isDebugEnabled() || isDetailedGCDryRun) { + DETAILED_GC_LOG.debug("Skipping removal of detailed garbage, cause no garbage detected"); } return; } monitor.info("Proceeding to update [{}] documents", updateOpList.size()); - if (log.isDebugEnabled() || isDetailedGCDryRun) { - String collect = updateOpList.stream().map(UpdateOp::getId).collect(joining(",")); - log.debug("Performing batch update of documents with following id's [{}]", collect); + if (DETAILED_GC_LOG.isDebugEnabled() || isDetailedGCDryRun) { + String updateIds = updateOpList.stream().map(UpdateOp::getId).collect(joining(", ")); + String orphanIds = join(", ", orphanOrDeletedRemovalMap.keySet()); + DETAILED_GC_LOG.debug("Performing batch update of ids [{}] and removal of orphan ids [{}]", updateIds, orphanIds); } if (cancel.get()) { - log.info("Aborting the removal of detailed garbage since RGC had been cancelled"); + DETAILED_GC_LOG.info("Aborting the removal of detailed garbage since RGC had been cancelled"); return; } @@ -1692,8 +1716,7 @@ public class VersionGarbageCollector { final UpdateOp update = it.next(); NodeDocument oldDoc = ds.find(Collection.NODES, update.getId()); if (oldDoc == null) { - log.error("removeGarbage.verify : no document found for update with id {}", - update.getId()); + DETAILED_GC_LOG.error("removeGarbage.verify : no document found for update with id {}", update.getId()); continue; } NodeState traversedParent = null; @@ -1707,13 +1730,11 @@ public class VersionGarbageCollector { oldDoc.deepCopy(newDoc); UpdateUtils.applyChanges(newDoc, update); // for the time being, verify both with classic and traversed - if (!verifyViaTraversedState(traversedState, traversedParent, - newDoc)) { + if (!verifyViaTraversedState(traversedState, traversedParent, newDoc)) { // verification failure // let's skip this document - if (log.isDebugEnabled()) { - log.debug("removeGarbage.verify : verifyViaTraversedState failed for {}", - newDoc.getId()); + if (DETAILED_GC_LOG.isDebugEnabled()) { + DETAILED_GC_LOG.debug("removeGarbage.verify : verifyViaTraversedState failed for {}", newDoc.getId()); } it.remove(); stats.skippedDetailedGCDocsCount++; @@ -1725,7 +1746,7 @@ public class VersionGarbageCollector { final Path path = orphanOrDeletedRemovalPathMap.get(id); if (path == null) { // rather a bug, so let's skip it - log.error("removeGarbage.verify : no path available for id : {}", id); + DETAILED_GC_LOG.error("removeGarbage.verify : no path available for id : {}", id); it.remove(); stats.skippedDetailedGCDocsCount++; continue; @@ -1736,9 +1757,8 @@ public class VersionGarbageCollector { if (!verifyDeletion(traversedState)) { // verification failure // let's skip this document - if (log.isDebugEnabled()) { - log.debug("removeGarbage.verify : verifyDeletion failed for {}", - e.getKey()); + if (DETAILED_GC_LOG.isDebugEnabled()) { + DETAILED_GC_LOG.debug("removeGarbage.verify : verifyDeletion failed for {}", e.getKey()); } it.remove(); stats.skippedDetailedGCDocsCount++; @@ -1760,8 +1780,8 @@ public class VersionGarbageCollector { stats.deletedDocGCCount += removedSize; stats.deletedOrphanNodesCount += removedSize; - if (log.isDebugEnabled()) { - log.debug("deleted [{}] documents (from intended {})", removedSize, orphanOrDeletedRemovalMap.size()); + if (DETAILED_GC_LOG.isDebugEnabled()) { + DETAILED_GC_LOG.debug("deleted [{}] documents (from intended {})", removedSize, orphanOrDeletedRemovalMap.size()); } // save stats @@ -1788,9 +1808,9 @@ public class VersionGarbageCollector { stats.deletedInternalPropRevsCount += deletedInternalRevEntriesCount; stats.deletedUnmergedBCCount += deletedUnmergedBCSet.size(); - if (log.isDebugEnabled()) { - log.debug("Updated [{}] documents, deleted [{}] properties, deleted [{}] unmergedBranchCommits", - updatedDocs, deletedProps, deletedUnmergedBCSet.size()); + if (DETAILED_GC_LOG.isDebugEnabled()) { + DETAILED_GC_LOG.debug("Updated [{}] docs, deleted [{}] props, deleted [{}] unmergedBCs, deleted [{}] internal Props, deleted [{}] prop revs, deleted [{}] internal prop revs", + updatedDocs, deletedProps, deletedUnmergedBCSet.size(), deletedInternalProps, deletedRevEntriesCount, deletedInternalRevEntriesCount); } // save stats @@ -1831,31 +1851,28 @@ public class VersionGarbageCollector { } } - private boolean verifyViaTraversedState(NodeState traversedState, NodeState traversedParent, - NodeDocument newDoc) { + private boolean verifyViaTraversedState(NodeState traversedState, NodeState traversedParent, NodeDocument newDoc) { final Path path = newDoc.getPath(); final Revision lastRevision = nodeStore.getPendingModifications().get(path); if (traversedParent == null && !newDoc.getPath().isRoot()) { - log.error("verify : no parent but not root for path : {}", newDoc.getPath()); + DETAILED_GC_LOG.error("verify : no parent but not root for path : {}", newDoc.getPath()); return false; } final RevisionVector lastRev; if (traversedParent == null && newDoc.getPath().isRoot()) { if (!(traversedState instanceof DocumentNodeState)) { - log.error("verify : traversedState not a DocumentNodeState : {}", - traversedState.getClass()); + DETAILED_GC_LOG.error("verify : traversedState not a DocumentNodeState : {}", traversedState.getClass()); return false; } lastRev = ((DocumentNodeState) traversedState).getLastRevision(); } else { if (!traversedParent.exists()) { // if the parent doesn't exist we shouldn't reach this point at all - log.error("verify : no parent but not marked for removal for path : {}", newDoc.getPath()); + DETAILED_GC_LOG.error("verify : no parent but not marked for removal for path : {}", newDoc.getPath()); return false; } if (!(traversedParent instanceof DocumentNodeState)) { - log.error("verify : traversedParent not a DocumentNodeState : {}", - traversedParent.getClass()); + DETAILED_GC_LOG.error("verify : traversedParent not a DocumentNodeState : {}", traversedParent.getClass()); return false; } lastRev = ((DocumentNodeState) traversedParent).getLastRevision(); @@ -1865,7 +1882,7 @@ public class VersionGarbageCollector { // (the faster state.equals() would stop if lastRev matches, // but as we're fiddling with immutability rule of a document, // we need to do a full check) - return AbstractNodeState.equals(traversedState, actual); + return nonNull(actual) && AbstractNodeState.equals(traversedState, actual); } private boolean verifyDeletion(NodeState traversedState) {
