Skip to content

Commit

Permalink
OAK-11401 : increased audit log level for VGC (#2024)
Browse files Browse the repository at this point in the history 
Co-authored-by: Rishabh Kumar <[email protected]>
  • Loading branch information
@rishabhdaim
rishabhdaim and Rishabh Kumar authored Jan 24, 2025
1 parent 68ab259 commit 298dec1
Showing 1 changed file with 25 additions and 31 deletions.
56 changes: 25 additions & 31 deletions ...ent/src/main/java/org/apache/jackrabbit/oak/plugins/document/VersionGarbageCollector.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1269,8 +1269,8 @@ private void combineInternalPropRemovals(final NodeDocument doc, final UpdateOp

// update the deleted properties count Map to calculate the total no. of deleted properties
int totalDeletedSystemPropsCount = deletedInternalPropsCountMap.merge(doc.getId(), deletedSystemPropsCount, Integer::sum);
if (AUDIT_LOG.isDebugEnabled() && totalDeletedSystemPropsCount > 0) {
AUDIT_LOG.debug("<Collected> [{}] internal prop revs in [{}] mode [{}]", totalDeletedSystemPropsCount, doc.getId(), fullGcMode);
if (AUDIT_LOG.isInfoEnabled() && totalDeletedSystemPropsCount > 0) {
AUDIT_LOG.info("<Collected> [{}] internal prop revs in [{}] mode [{}]", totalDeletedSystemPropsCount, doc.getId(), fullGcMode);
}
}
}
Expand Down Expand Up @@ -1348,9 +1348,7 @@ private boolean isDeletedOrOrphanedNode(final NodeState traversedState, final Pa
orphanOrDeletedRemovalPathMap.put(doc.getId(), doc.getPath());
fullGCStats.candidateDocuments(GCPhase.FULL_GC_COLLECT_ORPHAN_NODES, 1);

if (AUDIT_LOG.isDebugEnabled()) {
AUDIT_LOG.debug("<Collected> [{}] orphaned node", doc.getId());
}
AUDIT_LOG.info("<Collected> [{}] orphaned node in mode [{}]", doc.getId(), fullGcMode);

phases.stop(GCPhase.FULL_GC_COLLECT_ORPHAN_NODES);
return true;
Expand Down Expand Up @@ -1388,8 +1386,8 @@ private void collectDeletedProperties(final NodeDocument doc, final GCPhases pha
deletedPropsCountMap.put(doc.getId(), deletedPropsCount);
fullGCStats.candidateProperties(GCPhase.FULL_GC_COLLECT_PROPS, deletedPropsCount);

if (AUDIT_LOG.isDebugEnabled() && deletedPropsCount > 0) {
AUDIT_LOG.debug("<Collected> [{}] deleted props in [{}]", deletedPropsCount, doc.getId());
if (AUDIT_LOG.isInfoEnabled() && deletedPropsCount > 0) {
AUDIT_LOG.info("<Collected> [{}] deleted props in [{}]. Property Names [{}]", deletedPropsCount, doc.getId(), updateOp.getChanges().keySet());
}
phases.stop(GCPhase.FULL_GC_COLLECT_PROPS);
}
Expand Down Expand Up @@ -1427,8 +1425,8 @@ private void collectUnmergedBranchCommits(final NodeDocument doc, final GCPhases
olderUnmergedBranchCommits.forEach(bcRevision -> removeUnmergedBCRevision(bcRevision, doc, updateOp));
deletedUnmergedBCSet.addAll(olderUnmergedBranchCommits);

if (AUDIT_LOG.isDebugEnabled()) {
AUDIT_LOG.debug("<Collected> [{}] unmerged branch commits in [{}]", olderUnmergedBranchCommits.size(), doc.getId());
if (AUDIT_LOG.isInfoEnabled()) {
AUDIT_LOG.info("<Collected> [{}] unmerged branch commits in [{}]", olderUnmergedBranchCommits.size(), doc.getId());
}

// now for any of the handled system properties (the normal properties would
Expand Down Expand Up @@ -1459,8 +1457,8 @@ private void collectUnmergedBranchCommits(final NodeDocument doc, final GCPhases
int totalDeletedSystemPropsCount = deletedInternalPropsCountMap.merge(doc.getId(), deletedSystemPropsCount, Integer::sum);
fullGCStats.candidateInternalRevisions(GCPhase.FULL_GC_COLLECT_UNMERGED_BC, totalDeletedSystemPropsCount);

if (AUDIT_LOG.isDebugEnabled() && totalDeletedSystemPropsCount > 0) {
AUDIT_LOG.debug("<Collected> [{}] internal prop revs in [{}] mode [{}]", totalDeletedSystemPropsCount, doc.getId(), fullGcMode);
if (AUDIT_LOG.isInfoEnabled() && totalDeletedSystemPropsCount > 0) {
AUDIT_LOG.info("<Collected> [{}] internal prop revs in [{}] mode [{}]", totalDeletedSystemPropsCount, doc.getId(), fullGcMode);
}
}
phases.stop(GCPhase.FULL_GC_COLLECT_UNMERGED_BC);
Expand Down Expand Up @@ -1619,8 +1617,8 @@ private void removeUnmergedBCRevision(final Revision unmergedBCRevision, final N
fullGCStats.candidateRevisions(GCPhase.FULL_GC_COLLECT_UNMERGED_BC, revEntriesCount);
fullGCStats.candidateInternalRevisions(GCPhase.FULL_GC_COLLECT_UNMERGED_BC, internalRevEntriesCount);

if (AUDIT_LOG.isDebugEnabled() && (revEntriesCount > 0 || internalRevEntriesCount > 0)) {
AUDIT_LOG.debug("<Collected> [{}] prop revs, [{}] internal prop revs in [{}] mode [{}]", revEntriesCount, internalRevEntriesCount, doc.getId(), fullGcMode);
if (AUDIT_LOG.isInfoEnabled() && (revEntriesCount > 0 || internalRevEntriesCount > 0)) {
AUDIT_LOG.info("<Collected> [{}] prop revs, [{}] internal prop revs in [{}] mode [{}]", revEntriesCount, internalRevEntriesCount, doc.getId(), fullGcMode);
}

}
Expand All @@ -1640,8 +1638,8 @@ private void collectRevisionsOlderThan24hAndBetweenCheckpoints(final NodeDocumen
if (intRevsDiff > 0) {
deletedInternalPropRevsCountMap.merge(doc.getId(), intRevsDiff, Integer::sum);
}
if (AUDIT_LOG.isDebugEnabled() && (revsDiff > 0 || intRevsDiff > 0)) {
AUDIT_LOG.debug("<Collected> [{}] prop revs, [{}] internal prop revs in [{}] mode [{}]", revsDiff, intRevsDiff, doc.getId(), fullGcMode);
if (AUDIT_LOG.isInfoEnabled() && (revsDiff > 0 || intRevsDiff > 0)) {
AUDIT_LOG.info("<Collected> [{}] prop revs, [{}] internal prop revs in [{}] mode [{}]", revsDiff, intRevsDiff, doc.getId(), fullGcMode);
}
fullGCStats.candidateRevisions(GCPhase.FULL_GC_COLLECT_OLD_REVS, revsDiff);
fullGCStats.candidateInternalRevisions(GCPhase.FULL_GC_COLLECT_OLD_REVS, intRevsDiff);
Expand Down Expand Up @@ -1690,8 +1688,8 @@ private void collectUnusedPropertyRevisions(final NodeDocument doc,
deletedInternalPropRevsCountMap.merge(doc.getId(), deletedInternalRevsCount, Integer::sum);
}

if (AUDIT_LOG.isDebugEnabled() && deletedTotalRevsCount > 0) {
AUDIT_LOG.debug("<Collected> [{}] prop revs, [{}] internal prop revs in [{}] mode [{}]", deletedUserRevsCount, deletedInternalRevsCount, doc.getId(), fullGcMode);
if (AUDIT_LOG.isInfoEnabled() && deletedTotalRevsCount > 0) {
AUDIT_LOG.info("<Collected> [{}] prop revs, [{}] internal prop revs in [{}] mode [{}]", deletedUserRevsCount, deletedInternalRevsCount, doc.getId(), fullGcMode);
}
fullGCStats.candidateRevisions(GCPhase.FULL_GC_COLLECT_OLD_REVS, deletedUserRevsCount);
fullGCStats.candidateInternalRevisions(GCPhase.FULL_GC_COLLECT_OLD_REVS, deletedInternalRevsCount);
Expand Down Expand Up @@ -1924,18 +1922,18 @@ public void close() {
public void removeGarbage(final VersionGCStats stats) {

if (updateOpList.isEmpty() && orphanOrDeletedRemovalMap.isEmpty()) {
if (log.isDebugEnabled() || isFullGCDryRun) {
log.debug("Skipping removal of Full garbage, cause no garbage detected");
if (log.isInfoEnabled() || isFullGCDryRun) {
log.info("Skipping removal of Full garbage, cause no garbage detected");
}
return;
}

monitor.info("Proceeding to update [{}] documents", updateOpList.size());

if (AUDIT_LOG.isDebugEnabled() || isFullGCDryRun) {
if (AUDIT_LOG.isInfoEnabled() || isFullGCDryRun) {
String updateIds = updateOpList.stream().map(UpdateOp::getId).collect(joining(", "));
String orphanIds = join(", ", orphanOrDeletedRemovalMap.keySet());
log.debug("Performing batch update of ids [{}] and removal of orphan ids [{}]", updateIds, orphanIds);
AUDIT_LOG.info("Performing batch update of ids [{}] and removal of orphan ids [{}]", updateIds, orphanIds);
}

if (cancel.get()) {
Expand Down Expand Up @@ -1969,9 +1967,7 @@ public void removeGarbage(final VersionGCStats stats) {
if (!verifyViaTraversedState(traversedState, traversedParent, newDoc)) {
// verification failure
// let's skip this document
if (log.isDebugEnabled()) {
log.debug("removeGarbage.verify : verifyViaTraversedState failed for [{}]", newDoc.getId());
}
log.warn("removeGarbage.verify : verifyViaTraversedState failed for [{}]", newDoc.getId());
it.remove();
stats.skippedFullGCDocsCount++;
}
Expand All @@ -1993,9 +1989,7 @@ public void removeGarbage(final VersionGCStats stats) {
if (!verifyDeletion(traversedState)) {
// verification failure
// let's skip this document
if (log.isDebugEnabled()) {
log.debug("removeGarbage.verify : verifyDeletion failed for [{}]", e.getKey());
}
log.warn("removeGarbage.verify : verifyDeletion failed for [{}]", e.getKey());
it.remove();
stats.skippedFullGCDocsCount++;
}
Expand All @@ -2016,8 +2010,8 @@ public void removeGarbage(final VersionGCStats stats) {
stats.deletedDocGCCount += removedSize;
stats.deletedOrphanNodesCount += removedSize;

if (AUDIT_LOG.isDebugEnabled()) {
AUDIT_LOG.debug("<delete> [{}] documents (from intended {})", removedSize, orphanOrDeletedRemovalMap.size());
if (AUDIT_LOG.isInfoEnabled()) {
AUDIT_LOG.info("<delete> [{}] documents (from intended {})", removedSize, orphanOrDeletedRemovalMap.size());
}

// save stats
Expand All @@ -2044,8 +2038,8 @@ public void removeGarbage(final VersionGCStats stats) {
stats.deletedInternalPropRevsCount += deletedInternalRevEntriesCount;
stats.deletedUnmergedBCCount += deletedUnmergedBCSet.size();

if (log.isDebugEnabled()) {
log.debug("Updated [{}] docs, deleted [{}] props, deleted [{}] unmergedBCs, deleted [{}] internal Props, deleted [{}] prop revs, deleted [{}] internal prop revs",
if (log.isInfoEnabled()) {
log.info("Updated [{}] docs, deleted [{}] props, deleted [{}] unmergedBCs, deleted [{}] internal Props, deleted [{}] prop revs, deleted [{}] internal prop revs",
updatedDocs, deletedProps, deletedUnmergedBCSet.size(), deletedInternalProps, deletedRevEntriesCount, deletedInternalRevEntriesCount);
}

Expand Down

0 comments on commit 298dec1

Please sign in to comment.