Track histogram of transport handling times #80581

DaveCTurner · 2021-11-10T09:14:46Z

Adds to the transport node stats a record of the distribution of the
times for which a transport thread was handling a message, represented
as a histogram.

Closes #80428

Adds to the transport node stats a record of the distribution of the times for which a transport thread was handling a message, represented as a histogram. Closes elastic#80428

elasticmachine · 2021-11-10T09:14:50Z

Pinging @elastic/es-distributed (Team:Distributed)

DaveCTurner

I left some questions

DaveCTurner · 2021-11-10T09:15:57Z

server/src/main/java/org/elasticsearch/common/network/HandlingTimeTracker.java

+public class HandlingTimeTracker {
+
+    public static int[] getBucketUpperBounds() {
+        // Default clock resolution is 200ms so we have buckets for the 0-tick and 1-tick cases, then go up in powers of two


Should we use the raw time rather than the cached time so that we get better resolution?

Hmm we'd have to if we actually want fine grained resolution. I'd say it's ok, having fine grained information here is quite valuable/interesting and relative to the cost of reading from a channel etc, System.nanoTime should be trivial.

DaveCTurner · 2021-11-10T09:17:26Z

server/src/main/java/org/elasticsearch/transport/OutboundHandler.java

@@ -199,6 +209,7 @@ private void maybeLogSlowMessage(boolean success) {
                    final long logThreshold = slowLogThresholdMs;
                    if (logThreshold > 0) {
                        final long took = threadPool.relativeTimeInMillis() - startTime;
+                        handlingTimeTracker.addHandlingTime(took);


This may be spurious since it counts time spent waiting for the channel to become writeable (cf #77838). Should we track it separately from the inbound time tracking?

I don't think it's going to be possible to differentiate between waiting for writable and time spent actually writing really (I know I promised differently a while back sorry about that). Definitely not easily. If you think about it, you could run into a non-writable channel and start counting from there. But then once it becomes writable again, you might not be the first in line to get your bytes flushed because some other write comes before you and may turn the channel not-writable again. And then that other write takes CPU for TLS and such, making it really hard to cleanly define what time was spent waiting.

I really like the current number for the simple fact that it gives an indication for the latency overall on a transport thread (while the inbound handler check indicates individual per message slowness). I don't really see how we could cleanly identify the fact that a channel isn't writable for an extended period of time and pinpoint that on the network.

Yeah acking that we can't easily compute exactly what we want, but I still worry that we're putting two different numbers into the one histogram. Should we have two histograms, one for inbound things (which is purely handling-time) and one for outbound things (which potentially includes channel-blocked time)?

. Should we have two histograms, one for inbound things (which is purely handling-time) and one for outbound things (which potentially includes channel-blocked time)?

Yea that would be optimal actually. Can we do that here? :)

👍 done in c775e4e.

Another related observation is that we're not tracking outbound time for HTTP responses AFAICT. Should we? Can we?

Should we? Can we?

We could. I guess it would be nice to have but probably not all that valuable. The distribution on the outbound side for HTTP will be the same as that for sending transport messages. For REST outbound I'm almost thinking I'd rather like the distribution of serialization times there, because those have historically been the problem and it would give us more information when going on the hunt for why we have a bad distribution of outbound handling times.
IMO that'd be a worthwhile follow-up.

original-brownbear

I think I'd rather have a lower resolution here and eat the cost of uncached time lookups, but other than that LGTM (just some random questions/comments).
A finer resolution seems really valuable when it comes to debugging performance issues. If we're just over-under 200ms, then that wouldn't even allow us to cover current Authz issues much (they'd all fall under 200ms but still be an issue), nor would it allow measuring improvements. WDYT?

original-brownbear · 2021-11-24T15:33:22Z

server/src/main/java/org/elasticsearch/transport/OutboundHandler.java

@@ -199,6 +209,7 @@ private void maybeLogSlowMessage(boolean success) {
                    final long logThreshold = slowLogThresholdMs;
                    if (logThreshold > 0) {
                        final long took = threadPool.relativeTimeInMillis() - startTime;
+                        handlingTimeTracker.addHandlingTime(took);


I don't think it's going to be possible to differentiate between waiting for writable and time spent actually writing really (I know I promised differently a while back sorry about that). Definitely not easily. If you think about it, you could run into a non-writable channel and start counting from there. But then once it becomes writable again, you might not be the first in line to get your bytes flushed because some other write comes before you and may turn the channel not-writable again. And then that other write takes CPU for TLS and such, making it really hard to cleanly define what time was spent waiting.

I really like the current number for the simple fact that it gives an indication for the latency overall on a transport thread (while the inbound handler check indicates individual per message slowness). I don't really see how we could cleanly identify the fact that a channel isn't writable for an extended period of time and pinpoint that on the network.

original-brownbear · 2021-11-24T15:36:04Z

server/src/main/java/org/elasticsearch/transport/TransportStats.java

+    public int[] getHandlingTimeBucketBounds() {
+        final int[] bounds = new int[handlingTimeBucketBounds.length];
+        System.arraycopy(handlingTimeBucketBounds, 0, bounds, 0, handlingTimeBucketBounds.length);
+        return bounds;


NIT: I suppose you could use Arrays.copyOf or clone to shorten these to a single line :)

original-brownbear · 2021-11-24T15:41:08Z

server/src/main/java/org/elasticsearch/transport/TransportStats.java

@@ -42,6 +57,14 @@ public TransportStats(StreamInput in) throws IOException {
        rxSize = in.readVLong();
        txCount = in.readVLong();
        txSize = in.readVLong();
+        if (in.getVersion().onOrAfter(Version.V_8_1_0)) {
+            handlingTimeBucketFrequencies = in.readLongArray();
+            handlingTimeBucketBounds = in.readIntArray();


Why write these over the wire when they're hard coded per version anyway? :) I guess we need it to make BwC safe?

DaveCTurner

Everything addressed I think

DaveCTurner · 2021-11-25T15:18:47Z

server/src/main/java/org/elasticsearch/transport/OutboundHandler.java

@@ -199,6 +209,7 @@ private void maybeLogSlowMessage(boolean success) {
                    final long logThreshold = slowLogThresholdMs;
                    if (logThreshold > 0) {
                        final long took = threadPool.relativeTimeInMillis() - startTime;
+                        handlingTimeTracker.addHandlingTime(took);


Yeah acking that we can't easily compute exactly what we want, but I still worry that we're putting two different numbers into the one histogram. Should we have two histograms, one for inbound things (which is purely handling-time) and one for outbound things (which potentially includes channel-blocked time)?

original-brownbear

LGTM, I'm assuming the BwC test is unrelated.

…1-05-blocked-time-histogram

DaveCTurner · 2021-11-29T12:18:07Z

SLES workers are broken it seems. @elasticmachine please run elasticsearch-ci/rest-compatibility

DaveCTurner · 2021-11-29T13:55:28Z

SLES workers still failing to report successful builds.

@elasticmachine please run elasticsearch-ci/part-1
@elasticmachine please run elasticsearch-ci/rest-compatibility

* upstream/master: (150 commits) Fix ComposableIndexTemplate equals when composed_of is null (elastic#80864) Optimize DLS bitset building for matchAll query (elastic#81030) URL option for BaseRunAsSuperuserCommand (elastic#81025) Less Verbose Serialization of Snapshot Failure in SLM Metadata (elastic#80942) Fix shadowed vars pt7 (elastic#80996) Fail shards early when we can detect a type missmatch (elastic#79869) Delegate Ref Counting to ByteBuf in Netty Transport (elastic#81096) Clarify `unassigned.reason` docs (elastic#81017) Strip blocks from settings for reindex targets (elastic#80887) Split off the values supplier for ScriptDocValues (elastic#80635) [ML] Switch message and detail for model snapshot deprecations (elastic#81108) [DOCS] Update xrefs for snapshot restore docs (elastic#81023) [ML] Updates visiblity of validate API (elastic#81061) Track histogram of transport handling times (elastic#80581) [ML] Fix datafeed preview with remote indices (elastic#81099) [ML] Fix acceptable model snapshot versions in ML deprecation checker (elastic#81060) [ML] Add logging for failing PyTorch test (elastic#81044) Extending the timeout waiting for snapshot to be ready (elastic#81018) [ML] Fix incorrect logging of unexpected model size error (elastic#81089) [ML] Make inference timeout test more reliable (elastic#81094) ... # Conflicts: # server/src/main/java/org/elasticsearch/index/mapper/NumberFieldMapper.java

* upstream/master: (55 commits) Fix ComposableIndexTemplate equals when composed_of is null (elastic#80864) Optimize DLS bitset building for matchAll query (elastic#81030) URL option for BaseRunAsSuperuserCommand (elastic#81025) Less Verbose Serialization of Snapshot Failure in SLM Metadata (elastic#80942) Fix shadowed vars pt7 (elastic#80996) Fail shards early when we can detect a type missmatch (elastic#79869) Delegate Ref Counting to ByteBuf in Netty Transport (elastic#81096) Clarify `unassigned.reason` docs (elastic#81017) Strip blocks from settings for reindex targets (elastic#80887) Split off the values supplier for ScriptDocValues (elastic#80635) [ML] Switch message and detail for model snapshot deprecations (elastic#81108) [DOCS] Update xrefs for snapshot restore docs (elastic#81023) [ML] Updates visiblity of validate API (elastic#81061) Track histogram of transport handling times (elastic#80581) [ML] Fix datafeed preview with remote indices (elastic#81099) [ML] Fix acceptable model snapshot versions in ML deprecation checker (elastic#81060) [ML] Add logging for failing PyTorch test (elastic#81044) Extending the timeout waiting for snapshot to be ready (elastic#81018) [ML] Fix incorrect logging of unexpected model size error (elastic#81089) [ML] Make inference timeout test more reliable (elastic#81094) ...

Transport handling times were added in elastic#80581 (8.1), we don't need assertions for version prior to that in 9.0

Track histogram of transport handling times

e48ee01

Adds to the transport node stats a record of the distribution of the times for which a transport thread was handling a message, represented as a histogram. Closes elastic#80428

DaveCTurner added >enhancement :Distributed Coordination/Network Http and internode communication implementations v8.1.0 labels Nov 10, 2021

DaveCTurner requested a review from original-brownbear November 10, 2021 09:14

elasticmachine added the Team:Distributed (Obsolete) Meta label for distributed team (obsolete). Replaced by Distributed Indexing/Coordination. label Nov 10, 2021

DaveCTurner commented Nov 10, 2021

View reviewed changes

original-brownbear reviewed Nov 24, 2021

View reviewed changes

DaveCTurner added 4 commits November 25, 2021 14:31

Merge branch 'master' into 2021-11-05-blocked-time-histogram

b7b2ec8

Use raw times for better granularity

0d29128

Finer-grained buckets

a1ce073

Bucket count & bounds are known, no need to send over the wire

b527e82

DaveCTurner commented Nov 25, 2021

View reviewed changes

DaveCTurner requested a review from original-brownbear November 25, 2021 15:19

DaveCTurner added 2 commits November 25, 2021 15:47

Separate inbound & outbound histograms

c775e4e

Fix docs

6a967b9

original-brownbear approved these changes Nov 25, 2021

View reviewed changes

DaveCTurner added 5 commits November 25, 2021 18:42

Merge branch 'master' into 2021-11-05-blocked-time-histogram

cd415c1

Merge branch 'master' into 2021-11-05-blocked-time-histogram

0e0ae90

Less magic

8419a2d

Merge branch 'master' into 2021-11-05-blocked-time-histogram

3ef1eff

Merge branch 'master' of github.com:elastic/elasticsearch into 2021-1…

90d2ef9

…1-05-blocked-time-histogram

DaveCTurner merged commit 54e0370 into elastic:master Nov 29, 2021

DaveCTurner deleted the 2021-11-05-blocked-time-histogram branch November 29, 2021 15:41

arteam added a commit to arteam/elasticsearch that referenced this pull request Oct 14, 2024

Simplfy TransportStats assertions in v9

00f255d

Transport handling times were added in elastic#80581 (8.1), we don't need assertions for version prior to that in 9.0

arteam mentioned this pull request Oct 14, 2024

Simplify TransportStats assertions in v9 #114700

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Track histogram of transport handling times #80581

Track histogram of transport handling times #80581

DaveCTurner commented Nov 10, 2021

elasticmachine commented Nov 10, 2021

DaveCTurner left a comment

DaveCTurner Nov 10, 2021

original-brownbear Nov 24, 2021

DaveCTurner Nov 10, 2021

original-brownbear Nov 24, 2021

DaveCTurner Nov 25, 2021

original-brownbear Nov 25, 2021

DaveCTurner Nov 25, 2021

original-brownbear Nov 25, 2021

original-brownbear left a comment

original-brownbear Nov 24, 2021

original-brownbear Nov 24, 2021

original-brownbear Nov 24, 2021

DaveCTurner left a comment

DaveCTurner Nov 25, 2021

original-brownbear left a comment

DaveCTurner commented Nov 29, 2021

DaveCTurner commented Nov 29, 2021

Track histogram of transport handling times #80581

Track histogram of transport handling times #80581

Conversation

DaveCTurner commented Nov 10, 2021

elasticmachine commented Nov 10, 2021

DaveCTurner left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

original-brownbear left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

DaveCTurner left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

original-brownbear left a comment

Choose a reason for hiding this comment

DaveCTurner commented Nov 29, 2021

DaveCTurner commented Nov 29, 2021