HSEARCH-5180 Update logged message format

hibernate · Sep 6, 2024 · 34b5d56 · 34b5d56
1 parent 78666bd
commit 34b5d56
Show file tree

Hide file tree

Showing 5 changed files with 37 additions and 39 deletions.
diff --git a/...ate/search/integrationtest/mapper/orm/realbackend/massindexing/MassIndexingMonitorIT.java b/...ate/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/...ernate/search/integrationtest/mapper/pojo/massindexing/MassIndexingStreamingLoaderIT.java b/...ernate/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
@@ -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/.../org/hibernate/search/mapper/pojo/massindexing/impl/PojoMassIndexingBatchCoordinator.java b/.../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/...va/org/hibernate/search/mapper/pojo/massindexing/impl/PojoMassIndexingLoggingMonitor.java b/...va/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() {
 			}
 		}
 	}
-
 }