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