(jackrabbit-filevault) branch master updated: JCRVLT-762: Log/report node identifiers that cause import to switch to stashing … (#342)

[re...@apache.org]

This is an automated email from the ASF dual-hosted git repository.

reschke pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/jackrabbit-filevault.git


The following commit(s) were added to refs/heads/master by this push:
     new 3cc11d50 JCRVLT-762: Log/report node identifiers that cause import to switch to stashing … (#342)
3cc11d50 is described below

commit 3cc11d505b9fd31c0baec25fd3a5785deb74a83b
Author: Julian Reschke <ju...@gmx.de>
AuthorDate: Thu Jul 25 18:09:52 2024 +0200

    JCRVLT-762: Log/report node identifiers that cause import to switch to stashing … (#342)
    
    * JCRVLT-762: Log/report UUIDs that cause import to switch to stashing and sysview import, also report on slow stashing progress
    
    * JCRVLT-762: adjust for behavior of node.getPath() differing for removed nodes (Jackrabbit vs Oak)
    
    * JCRVLT-762: adjust logging to that for finish, the correct identifiers are logged
    
    * JCRVLT-762: lower logging level
---
 .../jackrabbit/vault/fs/impl/io/DocViewImporter.java      |  8 ++++++++
 .../org/apache/jackrabbit/vault/fs/impl/io/NodeStash.java | 15 +++++++++++++++
 2 files changed, 23 insertions(+)

diff --git a/vault-core/src/main/java/org/apache/jackrabbit/vault/fs/impl/io/DocViewImporter.java b/vault-core/src/main/java/org/apache/jackrabbit/vault/fs/impl/io/DocViewImporter.java
index e6af027a..3572276b 100644
--- a/vault-core/src/main/java/org/apache/jackrabbit/vault/fs/impl/io/DocViewImporter.java
+++ b/vault-core/src/main/java/org/apache/jackrabbit/vault/fs/impl/io/DocViewImporter.java
@@ -18,6 +18,7 @@ package org.apache.jackrabbit.vault.fs.impl.io;
 
 import java.io.IOException;
 import java.io.InputStream;
+import java.time.Duration;
 import java.util.ArrayList;
 import java.util.Calendar;
 import java.util.Collection;
@@ -990,6 +991,10 @@ public class DocViewImporter implements DocViewParserHandler {
         Optional<String> identifier = ni.getIdentifier();
         // try to set uuid via sysview import if it differs from existing one
         if (identifier.isPresent() && !node.getIdentifier().equals(identifier.get()) && !"rep:root".equals(ni.getPrimaryType().orElse(""))) {
+            long startTime = System.currentTimeMillis();
+            String previousIdentifier = node.getIdentifier();
+            log.debug("Node stashing for {} starting, existing identifier: {}, new identifier: {}, import mode: {}",
+                    node.getPath(), previousIdentifier, identifier.get(), importMode);
             NodeStash stash = new NodeStash(session, node.getPath());
             stash.stash(importInfo);
             Node parent = node.getParent();
@@ -997,6 +1002,9 @@ public class DocViewImporter implements DocViewParserHandler {
             node.remove();
             updatedNode = createNewNode(parent, ni);
             stash.recover(importMode, importInfo);
+            log.debug("Node stashing for {} finished, previous identifier: {}, new identifier: {}, elapsed: {}, import mode: {}",
+                    updatedNode.getPath(), previousIdentifier, updatedNode.getIdentifier(),
+                    Duration.ofMillis(System.currentTimeMillis() - startTime), importMode);
         } else {
             // TODO: is this faster than using sysview import?
             // set new primary type (but never set rep:root)
diff --git a/vault-core/src/main/java/org/apache/jackrabbit/vault/fs/impl/io/NodeStash.java b/vault-core/src/main/java/org/apache/jackrabbit/vault/fs/impl/io/NodeStash.java
index 0d7282e6..c36c11eb 100644
--- a/vault-core/src/main/java/org/apache/jackrabbit/vault/fs/impl/io/NodeStash.java
+++ b/vault-core/src/main/java/org/apache/jackrabbit/vault/fs/impl/io/NodeStash.java
@@ -16,10 +16,12 @@
  */
 package org.apache.jackrabbit.vault.fs.impl.io;
 
+import java.time.Duration;
 import java.util.Arrays;
 import java.util.HashSet;
 import java.util.List;
 import java.util.Set;
+import java.util.concurrent.TimeUnit;
 
 import javax.jcr.Node;
 import javax.jcr.NodeIterator;
@@ -63,6 +65,8 @@ public class NodeStash {
      */
     private static final String[] ROOTS = {"/tmp", "/var", "/etc", "/content", "/"};
 
+    /** interval for logging progress */
+    private static final long PROGRESS_LOG_INTERVAL = TimeUnit.MINUTES.toMillis(1);
 
     /** The property names of those protected properties which should be stashed (and later restored) */
     private static final List<String> PROTECTED_PROPERTIES_TO_STASH = Arrays.asList(JcrConstants.JCR_MIXINTYPES);
@@ -121,8 +125,11 @@ public class NodeStash {
 
             int childNodeCount = 0;
             int propertyCount = 0;
+            long start = System.currentTimeMillis();
+            long lastTimeStamp = start;
 
             NodeIterator nodeIterator = parent.getNodes();
+
             while (nodeIterator.hasNext()) {
                 Node child = nodeIterator.nextNode();
                 String name = child.getName();
@@ -134,6 +141,14 @@ public class NodeStash {
                     String path = child.getPath();
                     session.move(path, tmp.getPath() + "/" + name);
                     childNodeCount += 1;
+
+                    long now = System.currentTimeMillis();
+                    if (childNodeCount > 0 && now - PROGRESS_LOG_INTERVAL > lastTimeStamp) {
+                        log.warn("Node stashing operation {}, still running after {}, nodes moved: {}", this,
+                                Duration.ofMillis(now - start), childNodeCount);
+                        lastTimeStamp = now;
+                    }
+
                     if (importInfo != null) {
                         importInfo.onStashed(path);
                     }