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/sling-org-apache-sling-resourceresolver.git
The following commit(s) were added to refs/heads/master by this push:
new e0ab7a53 SLING-12917: ResourceResolver: alias refactoring - log
elapsed time for draining observation queue (#201)
e0ab7a53 is described below
commit e0ab7a53acc591605e7ef1dbecf687a63dbebceb
Author: Julian Reschke <[email protected]>
AuthorDate: Fri Aug 29 12:16:38 2025 +0200
SLING-12917: ResourceResolver: alias refactoring - log elapsed time for
draining observation queue (#201)
* SLING-12917: ResourceResolver: alias refactoring - log elapsed time for
draining observation queue
* SLING-12917: ResourceResolver: timing message utility - disallow null
message, fix documentation of param names, add nullability annotations
---
.../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..55b06869 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 description, duration, number of operations
+ // computes and inserts the number of operations per second
+ static @NotNull String getTimingMessage(@NotNull String description,
@NotNull Duration duration, long operations) {
+ StringBuilder result = new StringBuilder(description);
+
+ long nanos = duration.toNanos();
+ if (!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));
+ }
}
