Performance improvements in networking ExecuteProduceConsume engine

Keep track of when EPC engine can't spawn a new thread as this
might indicate thread-pool exhaustion and cause some network
messages to be lost.

If logging level is NOT 'trace' (or 'all') then don't call
System.currentTimeMillis() as we'll never use the value.

Similarly, don't set thread names if not logging at 'trace' either.

Update EPC tests, particularly unified per-second/end-of-test stats
reporting.

src/main/java/org/qortal/utils/ExecuteProduceConsume.java

@@ -20,6 +20,7 @@ public abstract class ExecuteProduceConsume implements Runnable {
 		public int consumerCount = 0;
 		public int tasksProduced = 0;
 		public int tasksConsumed = 0;
+		public int spawnFailures = 0;
 
 		public StatsSnapshot() {
 		}
@@ -27,6 +28,7 @@ public abstract class ExecuteProduceConsume implements Runnable {
 
 	private final String className;
 	private final Logger logger;
+	private final boolean isLoggerTraceEnabled;
 
 	private ExecutorService executor;
 
@@ -39,12 +41,14 @@ public abstract class ExecuteProduceConsume implements Runnable {
 	private volatile int consumerCount = 0;
 	private volatile int tasksProduced = 0;
 	private volatile int tasksConsumed = 0;
+	private volatile int spawnFailures = 0;
 
 	private volatile boolean hasThreadPending = false;
 
 	public ExecuteProduceConsume(ExecutorService executor) {
 		this.className = this.getClass().getSimpleName();
 		this.logger = LogManager.getLogger(this.getClass());
+		this.isLoggerTraceEnabled = this.logger.isTraceEnabled();
 
 		this.executor = executor;
 	}
@@ -75,6 +79,7 @@ public abstract class ExecuteProduceConsume implements Runnable {
 			snapshot.consumerCount = this.consumerCount;
 			snapshot.tasksProduced = this.tasksProduced;
 			snapshot.tasksConsumed = this.tasksConsumed;
+			snapshot.spawnFailures = this.spawnFailures;
 		}
 
 		return snapshot;
@@ -96,7 +101,8 @@ public abstract class ExecuteProduceConsume implements Runnable {
 
 	@Override
 	public void run() {
-		Thread.currentThread().setName(this.className + "-" + Thread.currentThread().getId());
+		if (this.isLoggerTraceEnabled)
+			Thread.currentThread().setName(this.className + "-" + Thread.currentThread().getId());
 
 		boolean wasThreadPending;
 		synchronized (this) {
@@ -131,10 +137,9 @@ public abstract class ExecuteProduceConsume implements Runnable {
 					this.logger.trace(() -> String.format("[%d] producing, activeThreadCount: %d, consumerCount: %d, canBlock is %b...",
 							Thread.currentThread().getId(), this.activeThreadCount, this.consumerCount, lambdaCanIdle));
 
-					final long now = System.currentTimeMillis();
+					final long beforeProduce = isLoggerTraceEnabled ? System.currentTimeMillis() : 0;
 					task = produceTask(canBlock);
-					final long delay = System.currentTimeMillis() - now;
+					this.logger.trace(() -> String.format("[%d] producing took %dms", Thread.currentThread().getId(), System.currentTimeMillis() - beforeProduce));
-					this.logger.trace(() -> String.format("[%d] producing took %dms", Thread.currentThread().getId(), delay));
 				}
 
 				if (task == null)
@@ -172,6 +177,7 @@ public abstract class ExecuteProduceConsume implements Runnable {
 						try {
 							this.executor.execute(this); // Same object, different thread
 						} catch (RejectedExecutionException e) {
+							++this.spawnFailures;
 							this.hasThreadPending = false;
 							this.logger.trace(() -> String.format("[%d] failed to spawn another thread", Thread.currentThread().getId()));
 						}
@@ -198,7 +204,8 @@ public abstract class ExecuteProduceConsume implements Runnable {
 		} catch (InterruptedException e) {
 			// We're in shutdown situation so exit
 		} finally {
-			Thread.currentThread().setName(this.className + "-dormant");
+			if (this.isLoggerTraceEnabled)
+				Thread.currentThread().setName(this.className);
 		}
 	}
 

src/test/java/org/qortal/test/EPCTests.java

@@ -61,12 +61,10 @@ public class EPCTests {
 		ScheduledExecutorService statusExecutor = Executors.newSingleThreadScheduledExecutor();
 
 		statusExecutor.scheduleAtFixedRate(() -> {
-			StatsSnapshot snapshot = testEPC.getStatsSnapshot();
+			final StatsSnapshot snapshot = testEPC.getStatsSnapshot();
 			final long seconds = (System.currentTimeMillis() - start) / 1000L;
-			System.out.println(String.format("After %d second%s, active threads: %d, greatest thread count: %d, tasks produced: %d, tasks consumed: %d",
+			System.out.print(String.format("After %d second%s, ", seconds, (seconds != 1 ? "s" : "")));
-					seconds, (seconds != 1 ? "s" : ""),
+			printSnapshot(snapshot);
-					snapshot.activeThreadCount, snapshot.greatestActiveThreadCount,
-					snapshot.tasksProduced, snapshot.tasksConsumed));
 		}, 1L, 1L, TimeUnit.SECONDS);
 
 		// Let it run for a minute
@@ -79,9 +77,16 @@ public class EPCTests {
 
 		System.out.println(String.format("Shutdown took %d milliseconds", after - before));
 
-		StatsSnapshot snapshot = testEPC.getStatsSnapshot();
+		final StatsSnapshot snapshot = testEPC.getStatsSnapshot();
-		System.out.println(String.format("Greatest thread count: %d, tasks produced: %d, tasks consumed: %d",
+		System.out.print("After shutdown, ");
-				snapshot.greatestActiveThreadCount, snapshot.tasksProduced, snapshot.tasksConsumed));
+		printSnapshot(snapshot);
+	}
+
+	private void printSnapshot(final StatsSnapshot snapshot) {
+		System.out.println(String.format("threads: %d active (%d max, %d exhaustion%s), tasks: %d produced / %d consumed",
+				snapshot.activeThreadCount, snapshot.greatestActiveThreadCount,
+				snapshot.spawnFailures, (snapshot.spawnFailures != 1 ? "s": ""),
+				snapshot.tasksProduced, snapshot.tasksConsumed));
 	}
 
 	@Test