log more information in a more predictable manner when inserting entries

performanceDb/src/main/java/org/lucares/performance/db/PerformanceDb.java

@@ -2,6 +2,7 @@ package org.lucares.performance.db;
 
 import java.io.IOException;
 import java.nio.file.Path;
+import java.time.Duration;
 import java.time.OffsetDateTime;
 import java.util.ArrayList;
 import java.util.Arrays;
@@ -63,11 +64,13 @@ public class PerformanceDb implements AutoCloseable {
 
 	public void put(final BlockingIterator<Entry> entries) throws WriteException {
 
-		final int blocksize = 100000;
+		final Duration timeBetweenSyncs = Duration.ofSeconds(10);
 		long count = 0;
+		long insertionsSinceLastSync = 0;
 
 		try {
-			long start = System.currentTimeMillis();
+			long lastSync = System.currentTimeMillis();
+			long nextSync = lastSync + timeBetweenSyncs.toMillis();
 
 			while (true) {
 				final Optional<Entry> entryOptional = nextEntry(entries);
@@ -84,20 +87,22 @@ public class PerformanceDb implements AutoCloseable {
 
 					writer.write(entry);
 					count++;
+					insertionsSinceLastSync++;
 
-					if (count % blocksize == 0) {
+					if (nextSync < System.currentTimeMillis()) {
 						final long end = System.currentTimeMillis();
-						final long duration = end - start;
-						METRICS_LOGGER.debug("inserting the last " + blocksize + " took " + duration
-								+ " ms; total entries: " + count / 1_000_000.0 + " million");
+						final long duration = end - lastSync;
+						final long entriesPerSecond = (long) (insertionsSinceLastSync / (duration / 1000.0));
 
-						start = System.currentTimeMillis();
-					}
+						METRICS_LOGGER
+								.debug(String.format("inserting %d/s ; the last %,d took %dms; total entries: %,d",
+										entriesPerSecond, insertionsSinceLastSync, duration, count));
 
-					if (count % blocksize == 0) {
-						final long startFlush = System.currentTimeMillis();
 						tagsToFile.flush();
-						LOGGER.debug("flushed all files: " + (System.currentTimeMillis() - startFlush) + "ms");
+
+						lastSync = System.currentTimeMillis();
+						nextSync = lastSync + timeBetweenSyncs.toMillis();
+						insertionsSinceLastSync = 0;
 					}
 
 				} catch (final InvalidValueException | SyntaxException e) {

performanceDb/src/main/java/org/lucares/performance/db/TagsToFile.java

@@ -193,7 +193,7 @@ public class TagsToFile implements AutoCloseable {
 	}
 
 	public void clearWriterCache() {
-		LOGGER.debug("close all cached writers");
+		LOGGER.info("close all cached writers");
 		final Iterator<Entry<Tags, WriterCache>> it = cachedWriters.entrySet().iterator();
 
 		while (it.hasNext()) {
@@ -274,6 +274,7 @@ public class TagsToFile implements AutoCloseable {
 	}
 
 	public void flush() {
+		final long startFlush = System.currentTimeMillis();
 		LOGGER.debug("flushing all writers");
 		forEachWriter(t -> {
 			try {
@@ -283,5 +284,6 @@ public class TagsToFile implements AutoCloseable {
 				throw new WriteException(e);
 			}
 		});
+		LOGGER.debug("flushed all files: " + (System.currentTimeMillis() - startFlush) + "ms");
 	}
 }