This is an automated email from the ASF dual-hosted git repository. cschneider pushed a commit to branch SLING-12429 in repository https://gitbox.apache.org/repos/asf/sling-org-apache-sling-distribution-journal.git
commit f0fd31cd3683f271151534e957f7c4289f01e5fe Author: Christian Schneider <[email protected]> AuthorDate: Thu Sep 12 08:09:04 2024 +0200 SLING-12380 - Improve logging --- pom.xml | 10 +++++++++- .../sling/distribution/journal/bookkeeper/BookKeeper.java | 6 +++--- .../journal/impl/subscriber/DistributionSubscriber.java | 4 ++-- .../sling/distribution/journal/bookkeeper/BookKeeperTest.java | 3 ++- 4 files changed, 16 insertions(+), 7 deletions(-) diff --git a/pom.xml b/pom.xml index 6bbc9d5..8e95878 100644 --- a/pom.xml +++ b/pom.xml @@ -17,7 +17,9 @@ specific language governing permissions and limitations under the License. --> -<project xmlns="http://maven.apache.org/POM/4.0.0"; xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/maven-v4_0_0.xsd";> +<project xmlns="http://maven.apache.org/POM/4.0.0"; + xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; + xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/maven-v4_0_0.xsd";> <modelVersion>4.0.0</modelVersion> <!-- ======================================================================= --> @@ -182,6 +184,12 @@ <version>4.3.16</version> <scope>provided</scope> </dependency> + <dependency> + <groupId>org.jetbrains</groupId> + <artifactId>annotations</artifactId> + <scope>test</scope> + </dependency> + <!-- OSGi --> <dependency> diff --git a/src/main/java/org/apache/sling/distribution/journal/bookkeeper/BookKeeper.java b/src/main/java/org/apache/sling/distribution/journal/bookkeeper/BookKeeper.java index 489f6dd..860bf22 100644 --- a/src/main/java/org/apache/sling/distribution/journal/bookkeeper/BookKeeper.java +++ b/src/main/java/org/apache/sling/distribution/journal/bookkeeper/BookKeeper.java @@ -186,7 +186,7 @@ public class BookKeeper { } } - public void invalidateCache(PackageMessage pkgMsg, long offset) throws DistributionException { + public void invalidateCache(PackageMessage pkgMsg, long offset, long importStartTime) throws DistributionException { log.debug("Invalidating the cache for the package {} at offset={}", pkgMsg, offset); try (ResourceResolver resolver = getServiceResolver(SUBSERVICE_BOOKKEEPER)) { Map<String, Object> props = this.buildProcessorPropertiesFromMessage(pkgMsg); @@ -207,8 +207,8 @@ public class BookKeeper { Event event = new AppliedEvent(pkgMsg, config.getSubAgentName()).toEvent(); eventAdmin.postEvent(event); - - log.info("Invalidated the cache for the package {} at offset={}", pkgMsg, offset); + long currentImporturationMs = System.currentTimeMillis() - importStartTime; + log.info("Invalidated the cache for the package {} at offset={}. This took importDurationMs={}", pkgMsg, offset, currentImporturationMs); subscriberMetrics.getPackageStatusCounter(pkgMsg.getPubAgentName(), Status.IMPORTED).increment(); subscriberMetrics.getInvalidationProcessDuration().update((currentTimeMillis() - invalidationStartTime), TimeUnit.MILLISECONDS); diff --git a/src/main/java/org/apache/sling/distribution/journal/impl/subscriber/DistributionSubscriber.java b/src/main/java/org/apache/sling/distribution/journal/impl/subscriber/DistributionSubscriber.java index 9cc0d0d..daed791 100644 --- a/src/main/java/org/apache/sling/distribution/journal/impl/subscriber/DistributionSubscriber.java +++ b/src/main/java/org/apache/sling/distribution/journal/impl/subscriber/DistributionSubscriber.java @@ -386,12 +386,12 @@ public class DistributionSubscriber { PackageMessage.ReqType type = pkgMsg.getReqType(); try { idleCheck.busy(bookKeeper.getRetries(pkgMsg.getPubAgentName()), info.getCreateTime()); + long importStartTime = System.currentTimeMillis(); if (skip) { bookKeeper.removePackage(pkgMsg, info.getOffset()); } else if (type == INVALIDATE) { - bookKeeper.invalidateCache(pkgMsg, info.getOffset()); + bookKeeper.invalidateCache(pkgMsg, info.getOffset(), importStartTime); } else { - long importStartTime = System.currentTimeMillis(); bookKeeper.importPackage(pkgMsg, info.getOffset(), info.getCreateTime(), importStartTime); } } finally { diff --git a/src/test/java/org/apache/sling/distribution/journal/bookkeeper/BookKeeperTest.java b/src/test/java/org/apache/sling/distribution/journal/bookkeeper/BookKeeperTest.java index daed3bd..19c1f9a 100644 --- a/src/test/java/org/apache/sling/distribution/journal/bookkeeper/BookKeeperTest.java +++ b/src/test/java/org/apache/sling/distribution/journal/bookkeeper/BookKeeperTest.java @@ -197,7 +197,8 @@ public class BookKeeperTest { @Test public void testCacheInvalidation() throws DistributionException { try { - bookKeeper.invalidateCache(buildPackageMessage(PackageMessage.ReqType.INVALIDATE), 10); + long simulatedStartTime = currentTimeMillis() - Duration.ofMinutes(1).toMillis(); + bookKeeper.invalidateCache(buildPackageMessage(PackageMessage.ReqType.INVALIDATE), 10, simulatedStartTime); } finally { assertThat(bookKeeper.getRetries(PUB_AGENT_NAME), equalTo(0)); }
