From e0f024ef5c75b74ee5df68b905574fd380f9ed4c Mon Sep 17 00:00:00 2001 From: catbref Date: Mon, 23 Mar 2020 11:00:19 +0000 Subject: [PATCH] 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. --- .../qortal/utils/ExecuteProduceConsume.java | 17 ++++++++++----- src/test/java/org/qortal/test/EPCTests.java | 21 ++++++++++++------- 2 files changed, 25 insertions(+), 13 deletions(-) diff --git a/src/main/java/org/qortal/utils/ExecuteProduceConsume.java b/src/main/java/org/qortal/utils/ExecuteProduceConsume.java index 4fa35ee9..8be654e5 100644 --- a/src/main/java/org/qortal/utils/ExecuteProduceConsume.java +++ b/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(), delay)); + this.logger.trace(() -> String.format("[%d] producing took %dms", Thread.currentThread().getId(), System.currentTimeMillis() - beforeProduce)); } 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); } } diff --git a/src/test/java/org/qortal/test/EPCTests.java b/src/test/java/org/qortal/test/EPCTests.java index d03a787c..fe48af24 100644 --- a/src/test/java/org/qortal/test/EPCTests.java +++ b/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", - seconds, (seconds != 1 ? "s" : ""), - snapshot.activeThreadCount, snapshot.greatestActiveThreadCount, - snapshot.tasksProduced, snapshot.tasksConsumed)); + System.out.print(String.format("After %d second%s, ", seconds, (seconds != 1 ? "s" : ""))); + printSnapshot(snapshot); }, 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(); - System.out.println(String.format("Greatest thread count: %d, tasks produced: %d, tasks consumed: %d", - snapshot.greatestActiveThreadCount, snapshot.tasksProduced, snapshot.tasksConsumed)); + final StatsSnapshot snapshot = testEPC.getStatsSnapshot(); + System.out.print("After shutdown, "); + 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