diff --git a/server/src/main/java/org/elasticsearch/common/util/concurrent/QueueResizingEsThreadPoolExecutor.java b/server/src/main/java/org/elasticsearch/common/util/concurrent/QueueResizingEsThreadPoolExecutor.java index 14d1ad5b64638..983e4cf206b34 100644 --- a/server/src/main/java/org/elasticsearch/common/util/concurrent/QueueResizingEsThreadPoolExecutor.java +++ b/server/src/main/java/org/elasticsearch/common/util/concurrent/QueueResizingEsThreadPoolExecutor.java @@ -151,8 +151,14 @@ protected void afterExecute(Runnable r, Throwable t) { final long totalNanos = totalTaskNanos.addAndGet(taskNanos); final long taskExecutionNanos = timedRunnable.getTotalExecutionNanos(); - assert taskExecutionNanos >= 0 : "expected task to always take longer than 0 nanoseconds, got: " + taskExecutionNanos; - executionEWMA.addValue(taskExecutionNanos); + if (taskExecutionNanos > 0) { + executionEWMA.addValue(taskExecutionNanos); + } else { + // wrapper (e.g. ContextPreservingAbstractRunnable) threw an exception before being able to run this task + assert taskExecutionNanos == -1 && timedRunnable.isStarted() == false && t != null : + "expected task exceptionally never to have started, but got: " + + taskExecutionNanos + " for " + timedRunnable + " with exception [" + t + "]"; + } if (taskCount.incrementAndGet() == this.tasksPerFrame) { final long endTimeNs = System.nanoTime(); diff --git a/server/src/main/java/org/elasticsearch/common/util/concurrent/TimedRunnable.java b/server/src/main/java/org/elasticsearch/common/util/concurrent/TimedRunnable.java index b6b9ef1ad05bf..fe09e903a9193 100644 --- a/server/src/main/java/org/elasticsearch/common/util/concurrent/TimedRunnable.java +++ b/server/src/main/java/org/elasticsearch/common/util/concurrent/TimedRunnable.java @@ -39,6 +39,7 @@ class TimedRunnable extends AbstractRunnable implements WrappedRunnable { @Override public void doRun() { try { + assert finishTimeNanos == -1 : "task already run: finishTimeNanos=" + finishTimeNanos + " for " + this; startTimeNanos = System.nanoTime(); original.run(); } finally { @@ -82,7 +83,6 @@ public boolean isForceExecution() { */ long getTotalNanos() { if (finishTimeNanos == -1) { - // There must have been an exception thrown, the total time is unknown (-1) return -1; } return Math.max(finishTimeNanos - creationTimeNanos, 1); @@ -93,8 +93,7 @@ long getTotalNanos() { * If the task is still running or has not yet been run, returns -1. */ long getTotalExecutionNanos() { - if (startTimeNanos == -1 || finishTimeNanos == -1) { - // There must have been an exception thrown, the total time is unknown (-1) + if (finishTimeNanos == -1) { return -1; } return Math.max(finishTimeNanos - startTimeNanos, 1); @@ -105,4 +104,15 @@ public Runnable unwrap() { return original; } + @Override + public String toString() { + return "TimedRunnable{" + + "original=" + original + + '}'; + } + + // used by assertions only + public boolean isStarted() { + return startTimeNanos != 0; + } }