Add timing stats to publication process #76771

DaveCTurner · 2021-08-20T15:27:13Z

This commit introduces into the node stats API various statistics to
track the time that the elected master spends in various phases of the
cluster state publication process.

Relates #76625

This commit introduces into the node stats API various statistics to track the time that the elected master spends in various phases of the cluster state publication process. Relates elastic#76625

DaveCTurner

The changes to Coordinator and MasterService are pretty much the only content here, everything else is just plumbing and other boilerplate. Adding 19 statistics in one go generates a lot of noise.

DaveCTurner · 2021-08-20T15:29:41Z

rest-api-spec/src/yamlRestTest/resources/rest-api-spec/test/nodes.stats/30_discovery.yml

@@ -40,3 +40,99 @@
  - gte: { nodes.$master.discovery.published_cluster_states.incompatible_diffs: 0 }
  - gte: { nodes.$master.discovery.published_cluster_states.compatible_diffs: 0 }
  - is_false:  nodes.$master.roles
+
+---
+"Master timing stats":


Really just asserting that the stats really do come out of the API and that we do the right thing with ?human.

DaveCTurner · 2021-08-20T15:30:33Z

server/src/main/java/org/elasticsearch/cluster/ClusterStatePublicationEvent.java

+        return ifSet(masterApplyElapsedMillis);
+    }
+
+    private static long ifSet(long millis) {


Used by the maybeGet functions for failed-publication stats since the failure could happen at any stage.

DaveCTurner · 2021-08-20T15:32:35Z

server/src/main/java/org/elasticsearch/cluster/service/MasterService.java

@@ -881,4 +900,91 @@ public void onNonemptyQueue() {
        }
    }

+    private static class TimingStatisticsTracker {


All methods synchronized (but very fast) just to avoid getting partially-updated stats.

elasticmachine · 2021-08-20T17:32:15Z

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

dakrone

This generally looks good, thanks for working on this @DaveCTurner! My one concern however is using the CachedTimeThread for calculating the times rather than raw System.nanoTime(). I think if we have a bunch of sub-200ms operations they'll appear to have completed instantaneously while the count is increasing, unless I am mistaken in the implementation. This inaccuracy seems like it will be very confusing for a user (and not to mention trying to graph/track stats like these).

dakrone · 2021-08-20T23:05:38Z

docs/reference/cluster/nodes-stats.asciidoc

+
+`success`::
+(object)
+Contains statistics about cluster state update attempts that did not change the


I think these are update attempts that did change the cluster state successfully?

Bah yes. Copy/paste might have been involved a bit here.

dakrone · 2021-08-20T23:09:26Z

server/src/main/java/org/elasticsearch/cluster/ClusterStatePublicationEvent.java

@@ -14,14 +14,30 @@
 */
 public class ClusterStatePublicationEvent {

+    private static final long NOT_SET = -1L;


Out of curiosity, why not just use 0 for NOT_SET instead of having a separate flag for it, especially since when retrieving the stats we adjust NOT_SET back to 0 anyway?

Really just to support the assertion that these things are set once and only once on each event. I added a comment in bd8ef0c.

dakrone · 2021-08-20T23:12:54Z

server/src/main/java/org/elasticsearch/cluster/coordination/Coordinator.java

                final PublicationTransportHandler.PublicationContext publicationContext =
                    publicationHandler.newPublicationContext(clusterStatePublicationEvent);
+                clusterStatePublicationEvent.setPublicationContextConstructionElapsedMillis(
+                    transportService.getThreadPool().relativeTimeInMillis() - publicationContextConstructionStartMillis);


Is there a concern that if this is < 200ms that it won't be counted with the use of the CachedTimeThread that only updates the clock every 200ms? Should this use "real" time instead?

My thinking was that if these things are only taking 200ms or so then we probably don't care, or more precisely we only care if they're happening with high frequency and in the high frequency case we will pick up the occasional 200ms clock tick with a probability that matches the mean duration, so on balance it'll all work out.

Also it's a pain to write tests that assert things about time when using System::nanoTime. I can fix up the assertions that say that at least T ms elapsed, but I'd just have to drop the ones with an upper bound. Maybe it's not that bad, the only one that I can't easily add an artificial delay to is the publication context construction.

I'll try out some ideas next week. Do you think we should accumulate the timers in nanoseconds too? Long.MAX_VALUE nanoseconds is ~300 years, I don't think there's much risk of overflow.

Ok in 9b0c5f3 I added a method to expose the raw (uncached) relative time to ThreadPool which we can still override to solve the testing pain, but which has better granularity. I stuck with milliseconds.

henningandersen

LGTM.

I would also prefer a more granular time measurement.

henningandersen · 2021-08-23T08:05:27Z

docs/reference/cluster/nodes-stats.asciidoc

+`commit_time`::
+(<<time-units,time value>>)
+The cumulative amount of time spent waiting for a successful cluster state
+update to _commit_, which happens when a majority of the master nodes have
+written the state to disk.
+
+`completion_time`::
+(<<time-units,time value>>)
+The cumulative amount of time spent waiting for a successful cluster state
+update to _complete_, which happens when all the nodes have applied the cluster
+state except for the elected master.


Perhaps clarify that these are from publication start, i.e., IIUC includes publication_time?

sure, see bee970a.

dakrone

LGTM, thanks for using the raw time!

DaveCTurner · 2021-08-23T16:43:59Z

Thanks both!

This commit introduces into the node stats API various statistics to track the time that the elected master spends in various phases of the cluster state publication process. Relates #76625

Adjusts the wire compatibility constraints and reverts commit 18e657a.

* master: (21 commits) [Test] More robust assertions for sorting and pagination (elastic#76654) [Test] Fix filename check on Windows (elastic#76807) Upgrade build scan plugin to 3.6.4 (elastic#76784) Remove keystore initial_md5sum (elastic#76835) Don't export docker images on assemble (elastic#76817) Fix testMasterStatsOnSuccessfulUpdate (elastic#76844) AwaitsFix for elastic#76840 Make Releasing Aggregation Buffers Safer (elastic#76741) Re-enable BWC tests after backport of elastic#76771 (elastic#76839) Dispatch large bulk requests to write thread (elastic#76736) Disable BWC tests for elastic#76771 Pull down beats artifacts when performing release tests Add timing stats to publication process (elastic#76771) Fix BanFailureLoggingTests some more (elastic#76668) Mention "warn threshold" in master service slowlog (elastic#76815) Fix DockerTests.test010Install Re-enable tests affected by elastic#75097 (elastic#76814) Fix testRecoveryIsCancelledAfterDeletingTheIndex (elastic#76644) Test fix -WildcardFieldMapperTests bad test data. (elastic#76819) Updating supported version after backporting the feature (elastic#76794) ... # Conflicts: # server/src/main/java/org/elasticsearch/action/bulk/TransportBulkAction.java

Add timing stats to publication process

9bdb2c9

This commit introduces into the node stats API various statistics to track the time that the elected master spends in various phases of the cluster state publication process. Relates elastic#76625

DaveCTurner added >enhancement :Distributed Coordination/Cluster Coordination Cluster formation and cluster state publication, including cluster membership and fault detection. v8.0.0 v7.16.0 labels Aug 20, 2021

DaveCTurner commented Aug 20, 2021

View reviewed changes

Hoisted by my own pedantic petard

211c13e

DaveCTurner marked this pull request as ready for review August 20, 2021 17:32

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

DaveCTurner requested a review from dakrone August 20, 2021 17:32

dakrone requested changes Aug 20, 2021

View reviewed changes

DaveCTurner added 7 commits August 21, 2021 10:39

Docs copy/paste error

eab60c3

Comment on NOT_SET

bd8ef0c

Check context-construction time is measured

8e7477a

Introduce ThreadPool#rawRelativeTimeInMillis

9b0c5f3

Precommit

be888f6

Moar docs

bd244dd

Rename master timing -> cluster state update stats

ab2fde0

henningandersen approved these changes Aug 23, 2021

View reviewed changes

More docs

bee970a

DaveCTurner requested a review from dakrone August 23, 2021 09:33

dakrone approved these changes Aug 23, 2021

View reviewed changes

DaveCTurner merged commit 4a17847 into elastic:master Aug 23, 2021

DaveCTurner deleted the 2021-08-20-master-publication-stats branch August 23, 2021 16:38

DaveCTurner added a commit that referenced this pull request Aug 23, 2021

Disable BWC tests for #76771

18e657a

DaveCTurner added a commit to DaveCTurner/elasticsearch that referenced this pull request Aug 23, 2021

Re-enable BWC tests after backport of elastic#76771

a1089b9

Adjusts the wire compatibility constraints and reverts commit 18e657a.

elasticsearchmachine pushed a commit that referenced this pull request Aug 23, 2021

Re-enable BWC tests after backport of #76771 (#76839)

7094493

Adjusts the wire compatibility constraints and reverts commit 18e657a.

DaveCTurner mentioned this pull request Aug 23, 2021

[CI] Zen1IT testMixedClusterFormation failing #76847

Closed

DaveCTurner mentioned this pull request Sep 9, 2021

Add timing stats for cluster state persistence #77511

Open

jakelandis added v8.0.0-alpha2 and removed v8.0.0 labels Sep 15, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add timing stats to publication process #76771

Add timing stats to publication process #76771

DaveCTurner commented Aug 20, 2021

DaveCTurner left a comment

DaveCTurner Aug 20, 2021

DaveCTurner Aug 20, 2021

DaveCTurner Aug 20, 2021

elasticmachine commented Aug 20, 2021

dakrone left a comment

dakrone Aug 20, 2021

DaveCTurner Aug 21, 2021

dakrone Aug 20, 2021

DaveCTurner Aug 21, 2021

dakrone Aug 20, 2021

DaveCTurner Aug 21, 2021

DaveCTurner Aug 23, 2021

henningandersen left a comment

henningandersen Aug 23, 2021

DaveCTurner Aug 23, 2021

dakrone left a comment

DaveCTurner commented Aug 23, 2021

Add timing stats to publication process #76771

Add timing stats to publication process #76771

Conversation

DaveCTurner commented Aug 20, 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

elasticmachine commented Aug 20, 2021

dakrone 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

henningandersen left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dakrone left a comment

Choose a reason for hiding this comment

DaveCTurner commented Aug 23, 2021