OAK-11284: Greedy Reuse of cluster IDs may lead to synchronous LastRe…

[mbaedke]

…vRecovery executions slowing down startup

Introduced the system variable oak.syncRecoveryTimeout to limit the duration of a self recovery at startup.

[sonarcloud]

Quality Gate passed

Issues
2 New issues
0 Accepted issues

Measures
0 Security Hotspots
57.1% Coverage on New Code
0.0% Duplication on New Code

See analysis details on SonarQube Cloud

[reschke]

Minor changes:

1. simplify sys property access
2. use custom clock used by LRA
3. log in ISO format and only if deadline changed
4. add logging for the case above

diff --git a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/LastRevRecoveryAgent.java b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/LastRevRecoveryAgent.java
index 0418751982..caa88e1b9a 100644
--- a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/LastRevRecoveryAgent.java
+++ b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/LastRevRecoveryAgent.java
@@ -29,11 +29,11 @@ import static org.apache.jackrabbit.oak.plugins.document.util.Utils.PROPERTY_OR_
 import static org.apache.jackrabbit.oak.plugins.document.util.Utils.isCommitted;
 import static org.apache.jackrabbit.oak.plugins.document.util.Utils.resolveCommitRevision;

-import java.text.SimpleDateFormat;
+import java.time.LocalDateTime;
+import java.time.ZoneOffset;
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.Collections;
-import java.util.Date;
 import java.util.List;
 import java.util.Map;
 import java.util.concurrent.TimeUnit;
@@ -82,7 +82,8 @@ public class LastRevRecoveryAgent {

     private final Consumer<Integer> afterRecovery;

-    private static final SystemPropertySupplier<Long> SYNC_RECOVERY_TIMEOUT_MILLIS = SystemPropertySupplier.create("oak.syncRecoveryTimeoutMillis", Long.MAX_VALUE);
+    private static final long SYNC_RECOVERY_TIMEOUT_MILLIS =
+            SystemPropertySupplier.create("oak.syncRecoveryTimeoutMillis", Long.MAX_VALUE).get();

     private static final long LOGINTERVALMS = TimeUnit.MINUTES.toMillis(1);

@@ -272,11 +273,19 @@ public class LastRevRecoveryAgent {
             ClusterNodeInfoDocument nodeInfo = missingLastRevUtil.getClusterNodeInfo(clusterId);
             if (nodeInfo != null && nodeInfo.isActive()) {
                 deadline = nodeInfo.getLeaseEndTime() - ClusterNodeInfo.DEFAULT_LEASE_FAILURE_MARGIN_MILLIS;
+                log.info("Deadline for synchronous recovery is {}.",
+                        LocalDateTime.ofEpochSecond(deadline, 0, ZoneOffset.UTC));
             }
-            long now = System.currentTimeMillis();
-            if (Long.MAX_VALUE - SYNC_RECOVERY_TIMEOUT_MILLIS.get() > now) {
-                deadline = Math.min(deadline, now + SYNC_RECOVERY_TIMEOUT_MILLIS.get());
-                log.info("Adjusted deadline for synchronous recovery. New deadline is {}", SimpleDateFormat.getDateTimeInstance().format(new Date(deadline)));
+            long now = revisionContext.getClock().millis();
+            // defensive: make sure we don't get an overflow below
+            if (Long.MAX_VALUE - SYNC_RECOVERY_TIMEOUT_MILLIS > now) {
+                long prevDeadline = deadline;
+                deadline = Math.min(deadline, now + SYNC_RECOVERY_TIMEOUT_MILLIS);
+                if (deadline != prevDeadline) {
+                    log.info("Adjusted deadline for synchronous recovery from {} to {}.",
+                            LocalDateTime.ofEpochSecond(prevDeadline, 0, ZoneOffset.UTC),
+                            LocalDateTime.ofEpochSecond(deadline, 0, ZoneOffset.UTC));
+                }
             }
         }

[stefan-egli]

haven't thought much about impact of this but just wanted to state (the obvious) that we'd need to be careful to not cause higher cluster IDs to be used than previously. The more cluster IDs that have ever been used in a deployment, the higher some cost (RevisionVector getting larger, some operations iterating over all (ever existing) cluster IDs)

[reschke]

@stefan-egli - that sort of is the point. It allows the user to trade conservative use of clusterIds with shorter startup time (which, in our case, was seen at around 10min when the server had been crashed and stayed off for a longer period of time)

[stefan-egli]

right, so this needs to be rolled out with care

[reschke]

well, it's opt-in...