From 34b5d56193b9a999d18024039b835a94af49c60e Mon Sep 17 00:00:00 2001 From: marko-bekhta Date: Thu, 5 Sep 2024 18:31:19 +0200 Subject: [PATCH] HSEARCH-5180 Update logged message format --- .../massindexing/MassIndexingMonitorIT.java | 14 ++++----- .../MassIndexingStreamingLoaderIT.java | 10 +++---- .../search/mapper/pojo/logging/impl/Log.java | 29 ++++++++++--------- .../PojoMassIndexingBatchCoordinator.java | 1 - .../impl/PojoMassIndexingLoggingMonitor.java | 22 +++++++------- 5 files changed, 37 insertions(+), 39 deletions(-) diff --git a/integrationtest/mapper/orm-realbackend/src/test/java/org/hibernate/search/integrationtest/mapper/orm/realbackend/massindexing/MassIndexingMonitorIT.java b/integrationtest/mapper/orm-realbackend/src/test/java/org/hibernate/search/integrationtest/mapper/orm/realbackend/massindexing/MassIndexingMonitorIT.java index a28a9cb3092..b45467cdea2 100644 --- a/integrationtest/mapper/orm-realbackend/src/test/java/org/hibernate/search/integrationtest/mapper/orm/realbackend/massindexing/MassIndexingMonitorIT.java +++ b/integrationtest/mapper/orm-realbackend/src/test/java/org/hibernate/search/integrationtest/mapper/orm/realbackend/massindexing/MassIndexingMonitorIT.java @@ -90,16 +90,14 @@ void testMassIndexingMonitor() { int expectedNumberOfLogs = NUMBER_OF_BOOKS / MASS_INDEXING_MONITOR_LOG_PERIOD; // Example: - // Mass indexing progress: indexed 151 entities in 21 ms. - logged.expectEvent( Level.INFO, "Mass indexing progress: indexed", "entities in", "ms" ).times( - expectedNumberOfLogs ); + // Indexed 75.50% 151/200. Per second: 8230.42 instant, 19755.16 overall. Remaining: 49, approximately PT0.005S. + logged.expectEvent( Level.INFO, "Indexed", "Per second", "Remaining:", "approximately PT" ) + .times( expectedNumberOfLogs ); // Example: - // Mass indexing progress: 26.50%. Mass indexing speed: 2765.605713 documents/second since last message, 2765.605713 documents/second since start. - logged.expectEvent( - Level.INFO, "Mass indexing progress:", "%", "Mass indexing speed:", - "documents/second since last message", "documents/second since start" - ).times( expectedNumberOfLogs ); + // Mass indexing complete in PT0.210155998S. Indexed 200/200 entities + logged.expectEvent( Level.INFO, "Mass indexing complete in", "Indexed 200/200 entities" ) + .times( 1 ); indexer.startAndWait(); } diff --git a/integrationtest/mapper/pojo-base/src/test/java/org/hibernate/search/integrationtest/mapper/pojo/massindexing/MassIndexingStreamingLoaderIT.java b/integrationtest/mapper/pojo-base/src/test/java/org/hibernate/search/integrationtest/mapper/pojo/massindexing/MassIndexingStreamingLoaderIT.java index fc8d30025c5..57ad742b13e 100644 --- a/integrationtest/mapper/pojo-base/src/test/java/org/hibernate/search/integrationtest/mapper/pojo/massindexing/MassIndexingStreamingLoaderIT.java +++ b/integrationtest/mapper/pojo-base/src/test/java/org/hibernate/search/integrationtest/mapper/pojo/massindexing/MassIndexingStreamingLoaderIT.java @@ -73,9 +73,9 @@ void oneAtATime() { expectIndexingWorks(); - logged.expectEvent( Level.INFO, "Mass indexing progress: indexed 50 entities", "(1 types pending)", - "Mass indexing speed:" ); - logged.expectEvent( Level.INFO, "Mass indexing progress: indexed", "1950/2000 entities in", "Mass indexing speed:" ); + logged.expectEvent( Level.INFO, "Indexed 50. Per second", "instant, ", "overall", + "Remaining: unknown, 1 type(s) pending" ); + logged.expectEvent( Level.INFO, "Indexed", "1950/2000. Per second", "Remaining: 50, approximately PT" ); try { mapping.scope( Object.class ).massIndexer() @@ -107,8 +107,8 @@ void allTogether() { expectIndexingWorks(); - logged.expectEvent( Level.INFO, "Mass indexing progress: indexed 50 entities", "Mass indexing speed:" ); - logged.expectEvent( Level.INFO, "Mass indexing progress: indexed", "1950/2000 entities in", "Mass indexing speed:" ); + logged.expectEvent( Level.INFO, "Indexed 50. Per second", "instant, ", "overall", "Remaining: unknown" ); + logged.expectEvent( Level.INFO, "Indexed", "1950/2000. Per second", "Remaining: 50, approximately PT" ); try { mapping.scope( Object.class ).massIndexer() diff --git a/mapper/pojo-base/src/main/java/org/hibernate/search/mapper/pojo/logging/impl/Log.java b/mapper/pojo-base/src/main/java/org/hibernate/search/mapper/pojo/logging/impl/Log.java index 0a15e2dfa8d..adf96c75e80 100644 --- a/mapper/pojo-base/src/main/java/org/hibernate/search/mapper/pojo/logging/impl/Log.java +++ b/mapper/pojo-base/src/main/java/org/hibernate/search/mapper/pojo/logging/impl/Log.java @@ -14,6 +14,7 @@ import java.net.URISyntaxException; import java.net.URL; import java.nio.file.Path; +import java.time.Duration; import java.util.Collection; import java.util.List; import java.util.Map; @@ -95,10 +96,6 @@ public interface Log extends BasicLogger { @Message(id = ID_OFFSET_LEGACY_ENGINE + 27, value = "Mass indexing is going to index %d entities.") void indexingEntities(long count); - @LogMessage(level = INFO) - @Message(id = ID_OFFSET_LEGACY_ENGINE + 28, value = "Mass indexing complete. Indexed %1$d entities.") - void indexingEntitiesCompleted(long nbrOfEntities); - @LogMessage(level = ERROR) @Message(id = ID_OFFSET_LEGACY_ENGINE + 62, value = "Mass indexing received interrupt signal: aborting.") void interruptedBatchIndexing(); @@ -1017,23 +1014,27 @@ SearchException usingNonDefaultValueConvertAndValueModelNotAllowed(String model, @LogMessage(level = INFO) @Message(id = ID_OFFSET + 163, - value = "Mass indexing progress: indexed %1$d entities in %3$d ms (%2$d type(s) pending). Mass indexing speed: %4$f documents/second since last message, %5$f documents/second since start.") - void indexingProgress(long doneCount, long typesToIndex, long elapsedMs, float currentSpeed, float estimateSpeed); + value = "Indexed %1$d. Per second: %3$.2f instant, %4$.2f overall. Remaining: unknown, %2$d type(s) pending.") + void indexingProgress(long doneCount, long typesToIndex, float currentSpeed, float estimateSpeed); @LogMessage(level = INFO) @Message(id = ID_OFFSET + 164, - value = "Mass indexing progress: indexed %1$d entities in %2$d ms. Mass indexing speed: %3$f documents/second since last message, %4$f documents/second since start.") - void indexingProgress(long doneCount, long elapsedMs, float currentSpeed, float estimateSpeed); + value = "Indexed %1$d. Per second: %2$.2f instant, %3$.2f overall. Remaining: unknown.") + void indexingProgress(long doneCount, float currentSpeed, float estimateSpeed); @LogMessage(level = INFO) @Message(id = ID_OFFSET + 165, - value = "Mass indexing progress: indexed %7$.2f%% %1$d/%2$d entities in %4$d ms (%3$d type(s) pending). Mass indexing speed: %5$f documents/second since last message, %6$f documents/second since start.") - void indexingProgress(long doneCount, long totalCount, long typesToIndex, long elapsedMs, float currentSpeed, - float estimateSpeed, float estimatePercentileComplete); + value = "Indexed %1$.2f%% %2$d/%3$d. Per second: %4$.2f instant, %5$.2f overall. Remaining: %6$d, %7$d type(s) pending.") + void indexingProgress(float estimatePercentileComplete, long doneCount, long totalCount, float currentSpeed, + float estimateSpeed, long remainingCount, long typesToIndex); @LogMessage(level = INFO) @Message(id = ID_OFFSET + 166, - value = "Mass indexing progress: indexed %6$.2f%% %1$d/%2$d entities in %3$d ms. Mass indexing speed: %4$f documents/second since last message, %5$f documents/second since start.") - void indexingProgress(long doneCount, long totalCount, long elapsedMs, float currentSpeed, float estimateSpeed, - float estimatePercentileComplete); + value = "Indexed %1$.2f%% %2$d/%3$d. Per second: %4$.2f instant, %5$.2f overall. Remaining: %6$d, approximately %7$s.") + void indexingProgressWithRemainingTime(float estimatePercentileComplete, long doneCount, long totalCount, + float currentSpeed, float estimateSpeed, long remainingCount, Duration timeToFinish); + + @LogMessage(level = INFO) + @Message(id = ID_OFFSET + 167, value = "Mass indexing complete in %3$s. Indexed %1$d/%2$d entities.") + void indexingEntitiesCompleted(long indexed, long total, Duration indexingTime); } diff --git a/mapper/pojo-base/src/main/java/org/hibernate/search/mapper/pojo/massindexing/impl/PojoMassIndexingBatchCoordinator.java b/mapper/pojo-base/src/main/java/org/hibernate/search/mapper/pojo/massindexing/impl/PojoMassIndexingBatchCoordinator.java index 1f47a9cfdf6..7e33c4bdea7 100644 --- a/mapper/pojo-base/src/main/java/org/hibernate/search/mapper/pojo/massindexing/impl/PojoMassIndexingBatchCoordinator.java +++ b/mapper/pojo-base/src/main/java/org/hibernate/search/mapper/pojo/massindexing/impl/PojoMassIndexingBatchCoordinator.java @@ -268,7 +268,6 @@ protected void notifyInterrupted(InterruptedException exception) { @Override protected void notifyFailure(RuntimeException exception) { super.notifyFailure( exception ); - // TODO HSEARCH-3729 Call a different method when indexing failed? getNotifier().reportIndexingCompleted(); } diff --git a/mapper/pojo-base/src/main/java/org/hibernate/search/mapper/pojo/massindexing/impl/PojoMassIndexingLoggingMonitor.java b/mapper/pojo-base/src/main/java/org/hibernate/search/mapper/pojo/massindexing/impl/PojoMassIndexingLoggingMonitor.java index c647a8a4574..0a2fe864288 100644 --- a/mapper/pojo-base/src/main/java/org/hibernate/search/mapper/pojo/massindexing/impl/PojoMassIndexingLoggingMonitor.java +++ b/mapper/pojo-base/src/main/java/org/hibernate/search/mapper/pojo/massindexing/impl/PojoMassIndexingLoggingMonitor.java @@ -5,8 +5,8 @@ package org.hibernate.search.mapper.pojo.massindexing.impl; import java.lang.invoke.MethodHandles; +import java.time.Duration; import java.util.OptionalLong; -import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicLong; import java.util.concurrent.atomic.AtomicReference; import java.util.concurrent.atomic.LongAdder; @@ -107,7 +107,8 @@ public void addToTotalCount(long count) { @Override public void indexingCompleted() { - log.indexingEntitiesCompleted( totalCounter.longValue() ); + log.indexingEntitiesCompleted( documentsDoneCounter.longValue(), totalCounter.longValue(), + Duration.ofNanos( System.nanoTime() - startTime ) ); } protected int getStatusMessagePeriod() { @@ -137,26 +138,26 @@ protected void printStatusMessage(long startTime, long currentTime, long totalTo if ( remainingUnknown ) { if ( typesToIndex > 0 ) { - log.indexingProgress( doneCount, typesToIndex, TimeUnit.NANOSECONDS.toMillis( elapsedNano ), currentSpeed, - estimateSpeed ); + log.indexingProgress( doneCount, typesToIndex, currentSpeed, estimateSpeed ); } else { - log.indexingProgress( doneCount, TimeUnit.NANOSECONDS.toMillis( elapsedNano ), currentSpeed, estimateSpeed ); + log.indexingProgress( doneCount, currentSpeed, estimateSpeed ); } } else { float estimatePercentileComplete = doneCount * 100f / totalTodoCount; + long remainingCount = totalTodoCount - doneCount; if ( typesToIndex > 0 ) { log.indexingProgress( - doneCount, totalTodoCount, typesToIndex, TimeUnit.NANOSECONDS.toMillis( elapsedNano ), currentSpeed, - estimateSpeed, estimatePercentileComplete + estimatePercentileComplete, doneCount, totalTodoCount, currentSpeed, estimateSpeed, + remainingCount, typesToIndex ); } else { - log.indexingProgress( - doneCount, totalTodoCount, TimeUnit.NANOSECONDS.toMillis( elapsedNano ), currentSpeed, estimateSpeed, - estimatePercentileComplete + log.indexingProgressWithRemainingTime( + estimatePercentileComplete, doneCount, totalTodoCount, currentSpeed, estimateSpeed, + remainingCount, Duration.ofMillis( (long) ( ( remainingCount / currentSpeed ) * 1000 ) ) ); } } @@ -209,5 +210,4 @@ public void indexingCompleted() { } } } - }