-
Notifications
You must be signed in to change notification settings - Fork 25.6k
Add allocation write load stats to write thread pool #130373
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Changes from 16 commits
4037ccf
b8d8e56
fd8f602
47debcd
37b20e8
be50439
45f6836
bd2e0f1
629ca35
b0fdaf2
46a659b
3ecac48
4986fa5
7ded14f
f942332
f9488fe
5057324
fb05d84
326f9e1
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -13,6 +13,8 @@ | |
| import org.elasticsearch.common.metrics.ExponentialBucketHistogram; | ||
| import org.elasticsearch.common.util.concurrent.EsExecutors.TaskTrackingConfig; | ||
| import org.elasticsearch.core.TimeValue; | ||
| import org.elasticsearch.logging.LogManager; | ||
| import org.elasticsearch.logging.Logger; | ||
| import org.elasticsearch.telemetry.metric.DoubleWithAttributes; | ||
| import org.elasticsearch.telemetry.metric.Instrument; | ||
| import org.elasticsearch.telemetry.metric.LongWithAttributes; | ||
|
|
@@ -27,6 +29,7 @@ | |
| import java.util.concurrent.RejectedExecutionHandler; | ||
| import java.util.concurrent.ThreadFactory; | ||
| import java.util.concurrent.TimeUnit; | ||
| import java.util.concurrent.atomic.LongAccumulator; | ||
| import java.util.concurrent.atomic.LongAdder; | ||
| import java.util.function.Function; | ||
|
|
||
|
|
@@ -37,6 +40,7 @@ | |
| * An extension to thread pool executor, which tracks statistics for the task execution time. | ||
| */ | ||
| public final class TaskExecutionTimeTrackingEsThreadPoolExecutor extends EsThreadPoolExecutor { | ||
| private static final Logger logger = LogManager.getLogger(TaskExecutionTimeTrackingEsThreadPoolExecutor.class); | ||
|
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. This The way I figured out is, https://github.com/elastic/logstash-filter-elastic_integration Logstash plugin minimally (
Thank you! There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. To close the loop here, I've put up a PR to remove the logger. Work is under way to address this on the Logstash module side, but it's a lot easier to change ES right now. |
||
|
|
||
| public static final int QUEUE_LATENCY_HISTOGRAM_BUCKETS = 18; | ||
| private static final int[] LATENCY_PERCENTILES_TO_REPORT = { 50, 90, 99 }; | ||
|
|
@@ -47,9 +51,17 @@ public final class TaskExecutionTimeTrackingEsThreadPoolExecutor extends EsThrea | |
| private final boolean trackOngoingTasks; | ||
| // The set of currently running tasks and the timestamp of when they started execution in the Executor. | ||
| private final Map<Runnable, Long> ongoingTasks = new ConcurrentHashMap<>(); | ||
| private volatile long lastPollTime = System.nanoTime(); | ||
| private volatile long lastTotalExecutionTime = 0; | ||
| private final ExponentialBucketHistogram queueLatencyMillisHistogram = new ExponentialBucketHistogram(QUEUE_LATENCY_HISTOGRAM_BUCKETS); | ||
| private final boolean trackMaxQueueLatency; | ||
| private LongAccumulator maxQueueLatencyMillisSinceLastPoll = new LongAccumulator(Long::max, 0); | ||
|
|
||
| public enum UtilizationTrackingPurpose { | ||
| APM, | ||
| ALLOCATION, | ||
| } | ||
|
|
||
| private volatile UtilizationTracker apmUtilizationTracker = new UtilizationTracker(); | ||
| private volatile UtilizationTracker allocationUtilizationTracker = new UtilizationTracker(); | ||
|
|
||
| TaskExecutionTimeTrackingEsThreadPoolExecutor( | ||
| String name, | ||
|
|
@@ -65,9 +77,11 @@ public final class TaskExecutionTimeTrackingEsThreadPoolExecutor extends EsThrea | |
| TaskTrackingConfig trackingConfig | ||
| ) { | ||
| super(name, corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory, handler, contextHolder); | ||
|
|
||
| this.runnableWrapper = runnableWrapper; | ||
| this.executionEWMA = new ExponentiallyWeightedMovingAverage(trackingConfig.getEwmaAlpha(), 0); | ||
| this.executionEWMA = new ExponentiallyWeightedMovingAverage(trackingConfig.getExecutionTimeEwmaAlpha(), 0); | ||
| this.trackOngoingTasks = trackingConfig.trackOngoingTasks(); | ||
| this.trackMaxQueueLatency = trackingConfig.trackMaxQueueLatency(); | ||
| } | ||
|
|
||
| public List<Instrument> setupMetrics(MeterRegistry meterRegistry, String threadPoolName) { | ||
|
|
@@ -95,7 +109,7 @@ public List<Instrument> setupMetrics(MeterRegistry meterRegistry, String threadP | |
| ThreadPool.THREAD_POOL_METRIC_PREFIX + threadPoolName + THREAD_POOL_METRIC_NAME_UTILIZATION, | ||
| "fraction of maximum thread time utilized for " + threadPoolName, | ||
| "fraction", | ||
| () -> new DoubleWithAttributes(pollUtilization(), Map.of()) | ||
| () -> new DoubleWithAttributes(pollUtilization(UtilizationTrackingPurpose.APM), Map.of()) | ||
| ) | ||
| ); | ||
| } | ||
|
|
@@ -136,37 +150,49 @@ public int getCurrentQueueSize() { | |
| return getQueue().size(); | ||
| } | ||
|
|
||
| public long getMaxQueueLatencyMillisSinceLastPollAndReset() { | ||
| if (trackMaxQueueLatency == false) { | ||
| return 0; | ||
| } | ||
| return maxQueueLatencyMillisSinceLastPoll.getThenReset(); | ||
| } | ||
|
|
||
| /** | ||
| * Returns the fraction of the maximum possible thread time that was actually used since the last time | ||
| * this method was called. | ||
| * Returns the fraction of the maximum possible thread time that was actually used since the last time this method was called. | ||
| * There are two periodic pulling mechanisms that access utilization reporting: {@link UtilizationTrackingPurpose} distinguishes the | ||
| * caller. | ||
| * | ||
| * @return the utilization as a fraction, in the range [0, 1] | ||
| * @return the utilization as a fraction, in the range [0, 1]. This may return >1 if a task completed in the time range but started | ||
| * earlier, contributing a larger execution time. | ||
| */ | ||
| public double pollUtilization() { | ||
| final long currentTotalExecutionTimeNanos = totalExecutionTime.sum(); | ||
| final long currentPollTimeNanos = System.nanoTime(); | ||
|
|
||
| final long totalExecutionTimeSinceLastPollNanos = currentTotalExecutionTimeNanos - lastTotalExecutionTime; | ||
| final long timeSinceLastPoll = currentPollTimeNanos - lastPollTime; | ||
| final long maximumExecutionTimeSinceLastPollNanos = timeSinceLastPoll * getMaximumPoolSize(); | ||
| final double utilizationSinceLastPoll = (double) totalExecutionTimeSinceLastPollNanos / maximumExecutionTimeSinceLastPollNanos; | ||
|
|
||
| lastTotalExecutionTime = currentTotalExecutionTimeNanos; | ||
| lastPollTime = currentPollTimeNanos; | ||
| return utilizationSinceLastPoll; | ||
| public double pollUtilization(UtilizationTrackingPurpose utilizationTrackingPurpose) { | ||
| switch (utilizationTrackingPurpose) { | ||
| case APM: | ||
| return apmUtilizationTracker.pollUtilization(); | ||
| case ALLOCATION: | ||
| return allocationUtilizationTracker.pollUtilization(); | ||
| default: | ||
| throw new IllegalStateException("No operation defined for [" + utilizationTrackingPurpose + "]"); | ||
| } | ||
nicktindall marked this conversation as resolved.
Show resolved
Hide resolved
|
||
| } | ||
|
|
||
| @Override | ||
| protected void beforeExecute(Thread t, Runnable r) { | ||
| if (trackOngoingTasks) { | ||
| ongoingTasks.put(r, System.nanoTime()); | ||
| } | ||
|
|
||
| assert super.unwrap(r) instanceof TimedRunnable : "expected only TimedRunnables in queue"; | ||
| final TimedRunnable timedRunnable = (TimedRunnable) super.unwrap(r); | ||
| timedRunnable.beforeExecute(); | ||
| final long taskQueueLatency = timedRunnable.getQueueTimeNanos(); | ||
| assert taskQueueLatency >= 0; | ||
| queueLatencyMillisHistogram.addObservation(TimeUnit.NANOSECONDS.toMillis(taskQueueLatency)); | ||
| var queueLatencyMillis = TimeUnit.NANOSECONDS.toMillis(taskQueueLatency); | ||
| queueLatencyMillisHistogram.addObservation(queueLatencyMillis); | ||
|
|
||
| if (trackMaxQueueLatency) { | ||
| maxQueueLatencyMillisSinceLastPoll.accumulate(queueLatencyMillis); | ||
| } | ||
| } | ||
|
|
||
| @Override | ||
|
|
@@ -222,7 +248,39 @@ public Map<Runnable, Long> getOngoingTasks() { | |
| } | ||
|
|
||
| // Used for testing | ||
| public double getEwmaAlpha() { | ||
| public double getExecutionEwmaAlpha() { | ||
| return executionEWMA.getAlpha(); | ||
| } | ||
|
|
||
| // Used for testing | ||
| public boolean trackingMaxQueueLatency() { | ||
| return trackMaxQueueLatency; | ||
| } | ||
|
|
||
| /** | ||
| * Supports periodic polling for thread pool utilization. Tracks state since the last polling request so that the average utilization | ||
| * since the last poll can be calculated for the next polling request. | ||
| * | ||
| * Uses the difference of {@link #totalExecutionTime} since the last polling request to determine how much activity has occurred. | ||
| */ | ||
| private class UtilizationTracker { | ||
| volatile long lastPollTime = System.nanoTime(); | ||
| volatile long lastTotalExecutionTime = 0; | ||
|
|
||
| public double pollUtilization() { | ||
DiannaHohensee marked this conversation as resolved.
Outdated
Show resolved
Hide resolved
|
||
| final long currentTotalExecutionTimeNanos = totalExecutionTime.sum(); | ||
| final long currentPollTimeNanos = System.nanoTime(); | ||
|
|
||
| final long totalExecutionTimeSinceLastPollNanos = currentTotalExecutionTimeNanos - lastTotalExecutionTime; | ||
| final long timeSinceLastPoll = currentPollTimeNanos - lastPollTime; | ||
|
|
||
| final long maximumExecutionTimeSinceLastPollNanos = timeSinceLastPoll * getMaximumPoolSize(); | ||
| final double utilizationSinceLastPoll = (double) totalExecutionTimeSinceLastPollNanos / maximumExecutionTimeSinceLastPollNanos; | ||
|
|
||
| lastTotalExecutionTime = currentTotalExecutionTimeNanos; | ||
| lastPollTime = currentPollTimeNanos; | ||
|
|
||
| return utilizationSinceLastPoll; | ||
| } | ||
| } | ||
nicktindall marked this conversation as resolved.
Show resolved
Hide resolved
|
||
| } | ||
Uh oh!
There was an error while loading. Please reload this page.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Nit: I think when you get to three consecutive booleans, it's worth making a builder for readability, e.g.
A side benefit would be you could default all to false and just specify the ones that were true.
Happy to be challenged on that.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
If we decide this is a good idea, also happy for it to be a separate PR because it'll add a fair bit of noise I imagine
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Sure, I'll put up a separate PR for this
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Alternatively I wonder if the max latency tracking is so cheap that we don't need to have a config for it. The ongoing task tracking is quite expensive, so it makes sense to be able to opt out of it. It would also reduce the surface area of this change.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
It seems a waste to track information unnecessarily, and potentially confusing wondering why it's not used. I'd prefer not to. Also never know how code will grow over time.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
To close this out, I've merged a TaskTrackingConfig Builder subclass and updated the callers with it.