This is an automated email from the ASF dual-hosted git repository. reschke pushed a commit to branch SLING-12917 in repository https://gitbox.apache.org/repos/asf/sling-org-apache-sling-resourceresolver.git
commit 1a59b62e19dd27679a8c788eb76800a5e8405e2f Author: Julian Reschke <[email protected]> AuthorDate: Thu Aug 28 12:50:46 2025 +0100 SLING-12917: ResourceResolver: alias refactoring - log elapsed time for draining observation queue --- .../impl/mapping/AliasHandler.java | 36 +++++++-------- .../resourceresolver/impl/mapping/MapEntries.java | 42 +++++++++++++++-- .../impl/mapping/VanityPathHandler.java | 53 +++++++++++----------- .../impl/mapping/MapEntriesTest.java | 17 +++++++ 4 files changed, 96 insertions(+), 52 deletions(-) diff --git a/src/main/java/org/apache/sling/resourceresolver/impl/mapping/AliasHandler.java b/src/main/java/org/apache/sling/resourceresolver/impl/mapping/AliasHandler.java index 4f1cdfe4..b8b3e961 100644 --- a/src/main/java/org/apache/sling/resourceresolver/impl/mapping/AliasHandler.java +++ b/src/main/java/org/apache/sling/resourceresolver/impl/mapping/AliasHandler.java @@ -29,12 +29,13 @@ import java.util.Optional; import java.util.Set; import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.CopyOnWriteArrayList; -import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicBoolean; import java.util.concurrent.atomic.AtomicLong; import java.util.concurrent.locks.ReentrantLock; +import java.util.function.Consumer; import java.util.stream.Collectors; +import org.apache.commons.lang3.time.StopWatch; import org.apache.sling.api.resource.LoginException; import org.apache.sling.api.resource.QuerySyntaxException; import org.apache.sling.api.resource.Resource; @@ -70,7 +71,7 @@ class AliasHandler { private final Runnable doUpdateConfiguration; private final Runnable sendChangeEvent; - private final Runnable drain; + private final Consumer<String> drain; // static value for the case when cache is not (yet) not initialized private static final Map<String, Map<String, Collection<String>>> UNITIALIZED_MAP = Collections.emptyMap(); @@ -97,7 +98,7 @@ class AliasHandler { @NotNull ReentrantLock initializing, @NotNull Runnable doUpdateConfiguration, @NotNull Runnable sendChangeEvent, - @NotNull Runnable drain) { + @NotNull Consumer<String> drain) { this.factory = factory; this.initializing = initializing; this.doUpdateConfiguration = doUpdateConfiguration; @@ -174,30 +175,23 @@ class AliasHandler { List<String> invalidAliases = new ArrayList<>(); StringBuilder diagnostics = new StringBuilder(); - long initStart = System.nanoTime(); + StopWatch sw = StopWatch.createStarted(); log.debug("alias initialization - start"); aliasMapsMap = loadAliases(resolver, conflictingAliases, invalidAliases, diagnostics); // process pending events - AliasHandler.this.drain.run(); + AliasHandler.this.drain.accept("draining alias event queue (during cache initialization)"); aliasesProcessed.set(true); // drain once more in case more events have arrived - AliasHandler.this.drain.run(); - - long processElapsed = System.nanoTime() - initStart; - long resourcePerSecond = (aliasResourcesOnStartup.get() - * TimeUnit.SECONDS.toNanos(1) - / (processElapsed == 0 ? 1 : processElapsed)); - log.info( - "alias initialization - completed, processed {} resources with sling:alias properties in {}ms (~{} resource/s){}", - aliasResourcesOnStartup.get(), - TimeUnit.NANOSECONDS.toMillis(processElapsed), - resourcePerSecond, - diagnostics); + AliasHandler.this.drain.accept("draining alias event queue (after cache initialization)"); + String message = MapEntries.getTimingMessage( + "alias initialization - completed", sw.getDuration(), aliasResourcesOnStartup.get()); + + log.info(message); } catch (Exception ex) { log.error("Alias init failed", ex); aliasMapsMap = UNITIALIZED_MAP; @@ -291,10 +285,12 @@ class AliasHandler { @NotNull private Iterator<Resource> queryUnpaged(@NotNull String query, @NotNull ResourceResolver resolver) { log.debug("start alias query: {}", query); - long queryStart = System.nanoTime(); + StopWatch sw = StopWatch.createStarted(); Iterator<Resource> it = resolver.findResources(query, "JCR-SQL2"); - long queryElapsed = System.nanoTime() - queryStart; - log.debug("end alias query; elapsed {}ms", TimeUnit.NANOSECONDS.toMillis(queryElapsed)); + log.debug( + "end alias query; elapsed {} ({}ms)", + sw.getDuration(), + sw.getDuration().toMillis()); return it; } } diff --git a/src/main/java/org/apache/sling/resourceresolver/impl/mapping/MapEntries.java b/src/main/java/org/apache/sling/resourceresolver/impl/mapping/MapEntries.java index de15d6a5..2378cf70 100644 --- a/src/main/java/org/apache/sling/resourceresolver/impl/mapping/MapEntries.java +++ b/src/main/java/org/apache/sling/resourceresolver/impl/mapping/MapEntries.java @@ -21,6 +21,7 @@ package org.apache.sling.resourceresolver.impl.mapping; import javax.servlet.http.HttpServletResponse; import java.io.IOException; +import java.time.Duration; import java.util.AbstractMap.SimpleEntry; import java.util.ArrayList; import java.util.Arrays; @@ -44,6 +45,7 @@ import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicBoolean; import java.util.concurrent.locks.ReentrantLock; +import org.apache.commons.lang3.time.StopWatch; import org.apache.sling.api.SlingConstants; import org.apache.sling.api.resource.LoginException; import org.apache.sling.api.resource.Resource; @@ -758,7 +760,8 @@ public class MapEntries implements MapEntriesHandler, ResourceChangeListener, Ex } // Drains the resource event queue for a specific queue - private boolean drainSpecificQueue(boolean isAlias, List<Map.Entry<String, ResourceChange.ChangeType>> queue) { + private boolean drainSpecificQueue( + boolean isAlias, String message, List<Map.Entry<String, ResourceChange.ChangeType>> queue) { final AtomicBoolean resolverRefreshed = new AtomicBoolean(false); // the config needs to be reloaded only once @@ -766,7 +769,11 @@ public class MapEntries implements MapEntriesHandler, ResourceChangeListener, Ex boolean sendEvent = false; + int count = 0; + StopWatch sw = StopWatch.createStarted(); + while (!queue.isEmpty()) { + count += 1; Map.Entry<String, ResourceChange.ChangeType> entry = queue.remove(0); final ResourceChange.ChangeType type = entry.getValue(); final String path = entry.getKey(); @@ -776,21 +783,46 @@ public class MapEntries implements MapEntriesHandler, ResourceChangeListener, Ex new ChangeContext(type, path, isAlias, !isAlias), resolverRefreshed, hasReloadedConfig); } + if (count > 0) { + log.info(getTimingMessage(message, sw.getDuration(), count)); + } + // do we need to send an event? return sendEvent; } // Drains the resource event queue for aliases - private void drainAliasQueue() { - if (drainSpecificQueue(true, resourceChangeQueueForAliases)) { + private void drainAliasQueue(String message) { + if (drainSpecificQueue(true, message, resourceChangeQueueForAliases)) { sendChangeEvent(); } } // Drains the resource event queue for vanity paths - private void drainVanityPathQueue() { - if (drainSpecificQueue(false, resourceChangeQueueForVanityPaths)) { + private void drainVanityPathQueue(String message) { + if (drainSpecificQueue(false, message, resourceChangeQueueForVanityPaths)) { sendChangeEvent(); } } + + // builds a string based on (optional) message, duration, number of operations + // computes and inserts the number of operations per second + static String getTimingMessage(String description, Duration duration, long operations) { + StringBuilder result = new StringBuilder(description); + + long nanos = duration.toNanos(); + if (description != null && !description.isEmpty()) { + result.append(": "); + } + + result.append(String.format( + "%s (%d ms) - %d operations", duration, TimeUnit.NANOSECONDS.toMillis(nanos), operations)); + + if (operations > 0) { + long operationsPerSecond = (operations * TimeUnit.SECONDS.toNanos(1) / (nanos == 0 ? 1 : nanos)); + result.append(String.format(" (~ %d operations/s)", operationsPerSecond)); + } + + return result.toString(); + } } diff --git a/src/main/java/org/apache/sling/resourceresolver/impl/mapping/VanityPathHandler.java b/src/main/java/org/apache/sling/resourceresolver/impl/mapping/VanityPathHandler.java index d9a21d65..8e83be5c 100644 --- a/src/main/java/org/apache/sling/resourceresolver/impl/mapping/VanityPathHandler.java +++ b/src/main/java/org/apache/sling/resourceresolver/impl/mapping/VanityPathHandler.java @@ -29,13 +29,14 @@ import java.util.List; import java.util.Map; import java.util.Objects; import java.util.concurrent.ConcurrentHashMap; -import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicBoolean; import java.util.concurrent.atomic.AtomicLong; import java.util.concurrent.locks.ReentrantLock; +import java.util.function.Consumer; import java.util.stream.Stream; import org.apache.commons.collections4.map.LRUMap; +import org.apache.commons.lang3.time.StopWatch; import org.apache.sling.api.resource.LoginException; import org.apache.sling.api.resource.QuerySyntaxException; import org.apache.sling.api.resource.Resource; @@ -93,13 +94,13 @@ public class VanityPathHandler { private final ReentrantLock initializing; - private final Runnable drain; + private final Consumer<String> drain; public VanityPathHandler( MapConfigurationProvider factory, Map<String, List<MapEntry>> resolveMapsMap, ReentrantLock initializing, - Runnable drain) { + Consumer<String> drain) { this.factory = factory; this.resolveMapsMap = resolveMapsMap; this.initializing = initializing; @@ -171,31 +172,24 @@ public class VanityPathHandler { try (ResourceResolver resolver = factory.getServiceResourceResolver(factory.getServiceUserAuthenticationInfo("mapping"))) { - long initStart = System.nanoTime(); + StopWatch sw = StopWatch.createStarted(); log.debug("vanity path initialization - start"); vanityTargets = loadVanityPaths(resolver); // process pending events - VanityPathHandler.this.drain.run(); + VanityPathHandler.this.drain.accept("draining vanity path event queue (during cache initialization)"); vanityPathsProcessed.set(true); // drain once more in case more events have arrived - VanityPathHandler.this.drain.run(); + VanityPathHandler.this.drain.accept("draining vanity path event queue (after cache initialization)"); - long initElapsed = System.nanoTime() - initStart; - long resourcesPerSecond = (vanityResourcesOnStartup.get() - * TimeUnit.SECONDS.toNanos(1) - / (initElapsed == 0 ? 1 : initElapsed)); - - log.info( - "vanity path initialization - completed, processed {} resources with sling:vanityPath properties in {}ms (~{} resource/s)", - vanityResourcesOnStartup.get(), - TimeUnit.NANOSECONDS.toMillis(initElapsed), - resourcesPerSecond); + String message = MapEntries.getTimingMessage( + "vanity path initialization - completed", sw.getDuration(), vanityResourcesOnStartup.get()); + log.info(message); } catch (LoginException ex) { - log.error("Vanity path init failed", ex); + log.error("vanity path init failed", ex); } finally { log.debug( "dropping temporary resolver map - {}/{} entries, {} hits, {} misses", @@ -471,7 +465,7 @@ public class VanityPathHandler { long count = 0; long countInScope = 0; - long processStart = System.nanoTime(); + StopWatch sw = StopWatch.createStarted(); while (it.hasNext()) { count += 1; @@ -484,12 +478,15 @@ public class VanityPathHandler { loadVanityPath(resource, resolveMapsMap, targetPaths, addToCache, true); } } - long processElapsed = System.nanoTime() - processStart; - log.debug( - "processed {} resources with sling:vanityPath properties (of which {} in scope) in {}ms", - count, - countInScope, - TimeUnit.NANOSECONDS.toMillis(processElapsed)); + + String message = MapEntries.getTimingMessage( + String.format( + "processed %d resources with sling:vanityPath properties (of which %d in scope)", + count, countInScope), + sw.getDuration(), + count); + log.debug(message); + if (!isAllVanityPathEntriesCached()) { if (countInScope > this.factory.getMaxCachedVanityPathEntries()) { log.warn( @@ -746,10 +743,12 @@ public class VanityPathHandler { private Iterator<Resource> queryUnpaged(String query, ResourceResolver resolver) { log.debug("start vanity path query: {}", query); - long queryStart = System.nanoTime(); + StopWatch sw = StopWatch.createStarted(); final Iterator<Resource> it = resolver.findResources(query, "JCR-SQL2"); - long queryElapsed = System.nanoTime() - queryStart; - log.debug("end vanity path query; elapsed {}ms", TimeUnit.NANOSECONDS.toMillis(queryElapsed)); + log.debug( + "end vanity path query; elapsed {} ({}ms)", + sw.getDuration(), + sw.getDuration().toMillis()); return it; } } diff --git a/src/test/java/org/apache/sling/resourceresolver/impl/mapping/MapEntriesTest.java b/src/test/java/org/apache/sling/resourceresolver/impl/mapping/MapEntriesTest.java index 9309dda9..237c5109 100644 --- a/src/test/java/org/apache/sling/resourceresolver/impl/mapping/MapEntriesTest.java +++ b/src/test/java/org/apache/sling/resourceresolver/impl/mapping/MapEntriesTest.java @@ -20,6 +20,7 @@ package org.apache.sling.resourceresolver.impl.mapping; import java.lang.reflect.Field; import java.lang.reflect.Method; +import java.time.Duration; import java.util.Collections; import java.util.Iterator; import java.util.LinkedList; @@ -221,4 +222,20 @@ public class MapEntriesTest extends AbstractMappingMapEntriesTest { mapEntries.ah.initializeAliases(); } + + @Test + public void testTimingFormatter() { + assertEquals( + "PT0S (0 ms) - 1 operations (~ 1000000000 operations/s)", + MapEntries.getTimingMessage("", Duration.ofNanos(0), 1)); + assertEquals( + "foobar: PT0S (0 ms) - 1 operations (~ 1000000000 operations/s)", + MapEntries.getTimingMessage("foobar", Duration.ofNanos(0), 1)); + assertEquals( + "PT3M (180000 ms) - 567 operations (~ 3 operations/s)", + MapEntries.getTimingMessage("", Duration.ofMinutes(3), 567)); + assertEquals( + "PT4H10M (15000000 ms) - 82304 operations (~ 5 operations/s)", + MapEntries.getTimingMessage("", Duration.ofMinutes(250), 82304)); + } }
