(jackrabbit-filevault) branch master updated: JCRVLT-836: log durations and number of nodes in AggregateImpl node walk (#409)

[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 1f28a42e JCRVLT-836: log durations and number of nodes in AggregateImpl node walk (#409)
1f28a42e is described below

commit 1f28a42edbe92d833a5735ff892c97dbf4d5b1a9
Author: Julian Reschke <ju...@gmx.de>
AuthorDate: Wed Jan 21 15:40:30 2026 +0100

    JCRVLT-836: log durations and number of nodes in AggregateImpl node walk (#409)
    
    * JCRVLT-836: log durations and number of nodes in AggregateImpl node walk
    
    * JCRVLT-836: log durations and number of nodes in AggregateImpl node walk - avoid timinh when nit DEBUG lebel
---
 .../jackrabbit/vault/fs/impl/AggregateImpl.java    | 38 ++++++++++++++++++++++
 1 file changed, 38 insertions(+)

diff --git a/vault-core/src/main/java/org/apache/jackrabbit/vault/fs/impl/AggregateImpl.java b/vault-core/src/main/java/org/apache/jackrabbit/vault/fs/impl/AggregateImpl.java
index 28b0e71b..525660fb 100644
--- a/vault-core/src/main/java/org/apache/jackrabbit/vault/fs/impl/AggregateImpl.java
+++ b/vault-core/src/main/java/org/apache/jackrabbit/vault/fs/impl/AggregateImpl.java
@@ -29,6 +29,7 @@ import javax.jcr.Value;
 
 import java.io.IOException;
 import java.lang.ref.WeakReference;
+import java.time.Duration;
 import java.util.ArrayList;
 import java.util.Collection;
 import java.util.Collections;
@@ -104,6 +105,8 @@ public class AggregateImpl implements Aggregate {
     private List<AggregateImpl> leaves;
 
     private String[] namespacePrefixes;
+    private long nodesVisitedForPrefixScanning;
+    private long siblingNodesInOrderedCollectionVisitedForPrefixScanning;
 
     private char state = STATE_INITIAL;
 
@@ -625,10 +628,25 @@ public class AggregateImpl implements Aggregate {
             }
             try {
                 load();
+                log.debug("starting namespace prefix walk of '{}'", this.path);
+                long start = log.isDebugEnabled() ? System.nanoTime() : -1;
                 Set<String> prefixes = new HashSet<String>();
                 // need to traverse the nodes to get all namespaces
                 loadNamespaces(prefixes, "", getNode());
                 namespacePrefixes = prefixes.toArray(new String[prefixes.size()]);
+
+                // set if and only if in DEBUG level
+                if (start >= 0) {
+                    Duration duration = Duration.ofNanos(System.nanoTime() - start);
+                    log.debug(
+                            "namespace prefix walk of '{}', visited {} nodes (of which {} siblings in ordered collections), prefixes: {}, elapsed {}ms, ({})",
+                            this.path,
+                            this.nodesVisitedForPrefixScanning,
+                            this.siblingNodesInOrderedCollectionVisitedForPrefixScanning,
+                            this.namespacePrefixes,
+                            duration.toMillis(),
+                            duration);
+                }
             } catch (RepositoryException e) {
                 throw new IllegalStateException("Internal error while loading namespaces", e);
             }
@@ -637,6 +655,7 @@ public class AggregateImpl implements Aggregate {
 
     private void loadNamespaces(Set<String> prefixes, String parentPath, Node node) throws RepositoryException {
         String name = node.getName();
+        nodesVisitedForPrefixScanning += 1;
         addNamespace(prefixes, name);
         for (PropertyIterator iter = node.getProperties(); iter.hasNext(); ) {
             Property p = iter.nextProperty();
@@ -655,8 +674,11 @@ public class AggregateImpl implements Aggregate {
             Node c = iter.nextNode();
             String relPath = parentPath + "/" + c.getName();
             if (includes(relPath)) {
+                nodesVisitedForPrefixScanning += 1;
                 loadNamespaces(prefixes, relPath, c);
             } else if (hasOrderableChildNodes) {
+                nodesVisitedForPrefixScanning += 1;
+                siblingNodesInOrderedCollectionVisitedForPrefixScanning += 1;
                 addNamespace(prefixes, c.getName());
             }
         }
@@ -719,10 +741,15 @@ public class AggregateImpl implements Aggregate {
         // get a node iterator suitable for the current node and the applicable filters
         NodeIterator nIter = getNodeIteratorFor(node, filter);
 
+        log.debug("starting aggregate walk of '{}'", this.path);
+        int visited = 0;
+        long startTime = log.isDebugEnabled() ? System.nanoTime() : -1;
+
         // include "our" nodes to the include set and delegate the others to the
         // respective aggregator building sub aggregates
         while (nIter.hasNext()) {
             Node n = nIter.nextNode();
+            visited += 1;
             String path = n.getPath();
             log.trace("checking {}", path);
 
@@ -780,6 +807,17 @@ public class AggregateImpl implements Aggregate {
                 }
             }
         }
+
+        // set if and only if in DEBUG level
+        if (startTime >= 0) {
+            Duration duration = Duration.ofNanos(System.nanoTime() - startTime);
+            log.debug(
+                    "aggregate walk of '{}', visited {} siblings in {}ms ({})",
+                    node.getPath(),
+                    visited,
+                    duration.toMillis(),
+                    duration);
+        }
     }
 
     private static NodeIterator getNodeIteratorFor(Node node, WorkspaceFilter filter) throws RepositoryException {