Add other time accounting in HotThreads #79392

grcevski · 2021-10-18T19:40:28Z

This PR introduces the concept of 'other' time in the HotThreads report. This 'other' time is calculated as the 'unknown' time the Java threads spend running, while they are not in a WAIT/BLOCKED state and are not using the CPU directly. Typically this 'other' time ends up being consumed by I/O or by the JVM itself, e.g. GC.

We are making the HotThreads CPU report sort by default by the 'Total' runnable time, which equals the CPU time + the 'Other' time. The original sort CPU report sort order can still be invoked through the REST API, by specifying &sort=cpu in the _nodes/hot_threads API url parameters. For example: _nodes/hot_threads?type=cpu&threads=1000000&sort=cpu.

Currently, the HotThreads CPU report contains only the CPU cycles that a thread executes, excluding time spent in I/O or the JVM runtime (e.g. GC). This PR introduces the 'other' time accounting to augment the CPU time for better understanding of user visible time impact.

grcevski · 2021-10-18T19:46:34Z

server/src/main/java/org/elasticsearch/bootstrap/Bootstrap.java

@@ -158,6 +159,20 @@ static void initializeProbes() {
        JvmInfo.jvmInfo();
    }

+    static void initializeRuntimeMonitoring() {


Enabling thread contention monitoring on-demand, as we used to do it in HotThreads, is not precise enough to properly calculate the wait/blocked time. If we enable the support on demand, we need to introduce an artificial pause before we attempt to capture timings, which would make the API unnecessarily slow.

I ran various micro benchmarks and proved that enabling lock contention monitoring by default, doesn't impact the performance of either uncontended or heavily contended use case.

grcevski · 2021-10-18T19:47:03Z

server/src/main/java/org/elasticsearch/monitor/jvm/HotThreads.java

@@ -57,7 +57,7 @@

    // NOTE: these are JVM dependent and JVM version dependent
    private static final List<String> knownJDKInternalThreads = Arrays.asList(
-        "Signal Dispatcher", "Finalizer", "Reference Handler", "Notification Thread", "Common-Cleaner", "process reaper"
+        "Signal Dispatcher", "Finalizer", "Reference Handler", "Notification Thread", "Common-Cleaner", "process reaper", "DestroyJavaVM"


DestroyJavaVM is one more of the JVM threads that don't do anything in particular.

grcevski · 2021-10-18T19:47:43Z

server/src/main/java/org/elasticsearch/monitor/jvm/HotThreads.java

+                ManagementFactory.getThreadMXBean(),
+                SunThreadInfo.INSTANCE,
+                Thread.currentThread().getId(),
+                (interval) -> {


This extra functional parameter was added to remove all timing delays when running the HotThreads unit tests.

This is great, thank you!

grcevski · 2021-10-18T19:48:34Z

server/src/main/java/org/elasticsearch/monitor/jvm/HotThreads.java

@@ -161,7 +198,7 @@ static boolean isIdleThread(ThreadInfo threadInfo) {
                continue;
            }
            long allocatedBytes = type == ReportType.MEM ? sunThreadInfo.getThreadAllocatedBytes(threadIds[i]) : 0;
-            result.put(threadIds[i], new ThreadTimeAccumulator(threadInfos[i], cpuTime, allocatedBytes));
+            result.put(threadIds[i], new ThreadTimeAccumulator(threadInfos[i], interval, cpuTime, allocatedBytes));


We pass in the supplied testing interval to HotThreads to be able to calculate the 'other' time, by subtracting the CPU, wait and blocked timings.

grcevski · 2021-10-18T19:49:22Z

server/src/main/java/org/elasticsearch/monitor/jvm/HotThreads.java

@@ -180,16 +217,22 @@ static boolean isIdleThread(ThreadInfo threadInfo) {
        return result;
    }

-    private void setThreadWaitBlockTimeMonitoringEnabled(ThreadMXBean threadBean, boolean enabled) {
+    private boolean isThreadWaitBlockTimeMonitoringEnabled(ThreadMXBean threadBean) {


We remove the privileged call to enable contention monitoring and replace it by simply checking if it's enabled. Bootstrap sets it by default ON now.

grcevski · 2021-10-18T19:50:12Z

server/src/main/java/org/elasticsearch/monitor/jvm/HotThreads.java

-        // Enabling thread contention monitoring is required for capturing JVM thread wait/blocked times
-        setThreadWaitBlockTimeMonitoringEnabled(threadBean, true);
+        // Capture before and after thread state with timings
+        Map<Long, ThreadTimeAccumulator> previousThreadInfos = getAllValidThreadInfos(threadBean, sunThreadInfo, currentThreadId);


These changes look bigger than they are, I simply removed the try/finally blocked since we don't need to disable thread contention monitoring at the end of the HotThreads innerDetect call anymore.

grcevski · 2021-10-18T19:51:06Z

server/src/main/java/org/elasticsearch/monitor/jvm/HotThreads.java

-            // Sort by delta CPU time on thread.
-            List<ThreadTimeAccumulator> topThreads = new ArrayList<>(latestThreadInfos.values());
-            final ToLongFunction<ThreadTimeAccumulator> getter = ThreadTimeAccumulator.valueGetterForReportType(type);
+        if (type == ReportType.CPU && sortOder == SortOrder.TOTAL)  {


When we sort by the 'total' runnable time, we first sort by the total time and then internally sort those at 100% by CPU.

grcevski · 2021-10-18T19:51:37Z

server/src/main/java/org/elasticsearch/monitor/jvm/HotThreads.java

+
+            // for each snapshot (2nd array index) find later snapshot for same thread with max number of
+            // identical StackTraceElements (starting from end of each)
+            boolean[] done = new boolean[threadElementsSnapshotCount];


This code below is unchanged.

grcevski · 2021-10-18T19:53:22Z

server/src/main/java/org/elasticsearch/monitor/jvm/HotThreads.java

-            this.blockedTime = info.getBlockedTime();
-            this.waitedTime = info.getWaitedTime();
+        ThreadTimeAccumulator(ThreadInfo info, TimeValue interval, long cpuTime, long allocatedBytes) {
+            this.blockedTime = millisecondsToNanos(info.getBlockedTime()); // Convert to nanos to standardize


This conversion here fixes an existing bug that I didn't notice before. Essentially, the ThreadInfo getWaitTime and getBlockedTime return the result in milliseconds, while CPU time is returned as nanoseconds. We used to produce incorrect wait times because we'd divide by interval.nanos().

Good catch. I wonder if this should be documented somewhere? At least in the support database as it may come up, and the fact this was fixed here could easily be lost since the PR is not directly about this bug (it could also be fixed in a separate PR, but I understand this PR may have tests which rely on it being fixed).

I was thinking about that, we should probably document that wait and blocked are fixed now. The millis to nanos is only an issue in 7.16 since I fixed the wait/blocked accounting there, previously we'd just report 0 always, so it doesn't matter what we divided with.

grcevski · 2021-10-18T19:55:09Z

server/src/test/java/org/elasticsearch/monitor/jvm/HotThreadsTests.java

@@ -32,6 +33,10 @@

 public class HotThreadsTests extends ESTestCase {

+    private long nanosHelper(long millis) {


Helper to ensure we correctly match results of wait/blocked timings given we internally convert the input mills to nanoseconds so we can accurately calculate the timings and percentages.

grcevski · 2021-10-18T19:56:51Z

server/src/test/java/org/elasticsearch/monitor/jvm/HotThreadsTests.java

-        assertThat(innerResult, containsString("30.0% (3nanos out of 10nanos) cpu usage by thread 'Thread 3'"));
-        assertThat(innerResult, containsString("20.0% (2nanos out of 10nanos) cpu usage by thread 'Thread 2'"));
-        assertThat(innerResult, containsString("10.0% (1nanos out of 10nanos) cpu usage by thread 'Thread 1'"));
+        assertThat(innerResult, stringContainsInOrder(


The changes in this method mainly focus on the updated output showing the separate 'cpu' and 'other' timings, as well as ensuring the orderings of output, since we have two sort modes now for CPU.

grcevski · 2021-10-18T19:58:36Z

server/src/test/java/org/elasticsearch/monitor/jvm/HotThreadsTests.java

        assertThat(exception.getMessage(), equalTo("thread allocated memory is not supported on this JDK"));
-
-        // making sure CPU type was not affected when isThreadAllocatedMemorySupported() == false


We don't need to do this extra test here, we already have tests that ensure CPU timings reporting works.

grcevski · 2021-10-18T20:01:57Z

server/src/main/resources/org/elasticsearch/bootstrap/security.policy

@@ -22,8 +22,6 @@ grant codeBase "${codebase.elasticsearch-secure-sm}" {
 grant codeBase "${codebase.elasticsearch}" {
  // needed for loading plugins which may expect the context class loader to be set
  permission java.lang.RuntimePermission "setContextClassLoader";
-  // needed by HotThreads to enable wait/block time accounting on demand


No longer needed since we now enable the monitoring before we install the security manager.

It's great to see permissions removed. :)

elasticmachine · 2021-10-18T20:02:39Z

Pinging @elastic/es-core-infra (Team:Core/Infra)

grcevski · 2021-10-18T20:03:56Z

...main/java/org/elasticsearch/action/admin/cluster/node/hotthreads/NodesHotThreadsRequest.java

@@ -20,8 +21,11 @@

 public class NodesHotThreadsRequest extends BaseNodesRequest<NodesHotThreadsRequest> {

+    private static final Version SORT_SUPPORTED_VERSION = Version.V_8_0_0;


Once we land this in 7_16_0, I'll change 8.0.0 to reflect that.

I prefer to see these versions directly in the streaminput ctor and writeTo methods. As a constant, it looks as if the value could just be changed, but it can't.

I also have a person preference for setting the version to the intended backport version from the start, but what you described is acceptable. Thanks for noting it.

Sounds good. Changed.

grcevski · 2021-10-19T11:53:11Z

@elasticmachine update branch

…icsearch into feature/hot_threads_other

grcevski · 2021-10-19T13:17:04Z

...test/java/org/elasticsearch/action/admin/cluster/hotthreads/NodesHotThreadsRequestTests.java

@@ -55,7 +55,7 @@ public void testBWCSerialization() throws IOException {
            out.setVersion(previous);
            request.writeTo(out);
            try (StreamInput in = out.bytes().streamInput()) {
-                in.setVersion(latest);
+                in.setVersion(previous);


I had this wrong before, out.bytes().streamInput() resets the original version that the out had before, so I had to forcibly set it to the old version to simulate 7.x sending over the request.

rjernst

LGTM. I have several comments, but they are mostly minor/ideas for followup.

rjernst · 2021-10-19T13:00:58Z

...main/java/org/elasticsearch/action/admin/cluster/node/hotthreads/NodesHotThreadsRequest.java

@@ -20,8 +21,11 @@

 public class NodesHotThreadsRequest extends BaseNodesRequest<NodesHotThreadsRequest> {

+    private static final Version SORT_SUPPORTED_VERSION = Version.V_8_0_0;


I also have a person preference for setting the version to the intended backport version from the start, but what you described is acceptable. Thanks for noting it.

rjernst · 2021-10-19T13:02:44Z

...main/java/org/elasticsearch/action/admin/cluster/node/hotthreads/NodesHotThreadsRequest.java

@@ -20,8 +21,11 @@

 public class NodesHotThreadsRequest extends BaseNodesRequest<NodesHotThreadsRequest> {

+    private static final Version SORT_SUPPORTED_VERSION = Version.V_8_0_0;
+
    int threads = 3;
    HotThreads.ReportType type = HotThreads.ReportType.CPU;


These should all be final, I'm surprised they are not. We should have a ctor to take all the members. That can be a followup, though (doesn't have to make 7.16 since this is already the state of the class).

rjernst · 2021-10-19T13:05:06Z

...main/java/org/elasticsearch/action/admin/cluster/node/hotthreads/NodesHotThreadsRequest.java

@@ -34,6 +38,9 @@ public NodesHotThreadsRequest(StreamInput in) throws IOException {
        type = HotThreads.ReportType.of(in.readString());
        interval = in.readTimeValue();
        snapshots = in.readInt();
+        if (in.getVersion().onOrAfter(SORT_SUPPORTED_VERSION)) {
+            sortOrder = HotThreads.SortOrder.of(in.readString());


It would be nice (as a followup) to look at changing read/write enum to use the value, instead of ordinal. As it is, the enum methods for stream input/output are brittle since they rely on the enum definition not changing.

rjernst · 2021-10-19T13:07:01Z

server/src/main/java/org/elasticsearch/bootstrap/Bootstrap.java

+    static void initializeRuntimeMonitoring() {
+        // We'll let the JVM boot without this functionality, however certain APIs like HotThreads will not
+        // function and report an error.
+        if (ManagementFactory.getThreadMXBean().isThreadContentionMonitoringSupported() == false) {


Can we do this in a static for hot threads still? Perhaps a static method could be called in initializeProbes? I think we should strive to keep Bootstrap as small as possible, without feature specific logic like this.

Good idea, I'll change this.

rjernst · 2021-10-19T13:10:34Z

server/src/main/java/org/elasticsearch/monitor/jvm/HotThreads.java

+            return order;
+        }
+
+        public static SortOrder of(String order) {


Can you remind me why valueOf can't work here, and leave a comment to that effect explaining why this method is needed?

The regular valueOf is a static method, we can't override it, and gives an ugly error message for the end user to see, something like 'field' is not member of full class name. But now that I think about it, I can possibly avoid the string serialization for this enum, I can just do writeEnum and readEnum, since I version the sort anyway. Let me look into that and this method can simply go away.

rjernst · 2021-10-19T13:11:24Z

server/src/main/java/org/elasticsearch/monitor/jvm/HotThreads.java

+                ManagementFactory.getThreadMXBean(),
+                SunThreadInfo.INSTANCE,
+                Thread.currentThread().getId(),
+                (interval) -> {


This is great, thank you!

rjernst · 2021-10-19T13:15:54Z

server/src/main/java/org/elasticsearch/monitor/jvm/HotThreads.java

-            // Sort by delta CPU time on thread.
-            List<ThreadTimeAccumulator> topThreads = new ArrayList<>(latestThreadInfos.values());
-            final ToLongFunction<ThreadTimeAccumulator> getter = ThreadTimeAccumulator.valueGetterForReportType(type);
+        if (type == ReportType.CPU && sortOder == SortOrder.TOTAL)  {


If we validate earlier that sortOrder is only present for type cpu, then we don't need to the type check on cpu?

rjernst · 2021-10-19T13:21:26Z

server/src/main/java/org/elasticsearch/monitor/jvm/HotThreads.java

-            this.blockedTime = info.getBlockedTime();
-            this.waitedTime = info.getWaitedTime();
+        ThreadTimeAccumulator(ThreadInfo info, TimeValue interval, long cpuTime, long allocatedBytes) {
+            this.blockedTime = millisecondsToNanos(info.getBlockedTime()); // Convert to nanos to standardize


Good catch. I wonder if this should be documented somewhere? At least in the support database as it may come up, and the fact this was fixed here could easily be lost since the PR is not directly about this bug (it could also be fixed in a separate PR, but I understand this PR may have tests which rely on it being fixed).

rjernst · 2021-10-19T13:22:51Z

server/src/main/resources/org/elasticsearch/bootstrap/security.policy

@@ -22,8 +22,6 @@ grant codeBase "${codebase.elasticsearch-secure-sm}" {
 grant codeBase "${codebase.elasticsearch}" {
  // needed for loading plugins which may expect the context class loader to be set
  permission java.lang.RuntimePermission "setContextClassLoader";
-  // needed by HotThreads to enable wait/block time accounting on demand


It's great to see permissions removed. :)

rjernst · 2021-10-19T13:24:21Z

server/src/test/java/org/elasticsearch/monitor/jvm/HotThreadsTests.java

+        assertThat(innerResult, containsString("0.0% [cpu=0.0%, other=0.0%] (0s out of 10ms) cpu usage by thread 'Thread 2'"));
+        assertThat(innerResult, containsString("0.0% [cpu=0.0%, other=0.0%] (0s out of 10ms) cpu usage by thread 'Thread 1'"));
+
+        // Test with the legacy sort order


There is a lot going on in this single test method. Can some of these cases be split into separate test methods?

Sounds good I'll get that done.

elasticsearchmachine · 2021-10-19T17:48:14Z

💔 Backport failed

Status	Branch	Result
❌	7.x	Commit could not be cherrypicked due to conflicts

You can use sqren/backport to manually backport by running backport --upstream elastic/elasticsearch --pr 79392

Backport of elastic#79392

This PR introduces the concept of 'other' time in the HotThreads report. Backport of #79392

* upstream/master: (24 commits) Implement framework for migrating system indices (elastic#78951) Improve transient settings deprecation message (elastic#79504) Remove getValue and getValues from Field (elastic#79516) Store Template's mappings as bytes for disk serialization (elastic#78746) [ML] Add queue_capacity setting to start deployment API (elastic#79433) [ML] muting rest compat test issue elastic#79518 (elastic#79519) Avoid redundant available indices check (elastic#76540) Re-enable BWC tests TEST Ensure password 14 chars length on Kerberos FIPS tests (elastic#79496) [DOCS] Temporarily remove APM links (elastic#79411) Fix CCSDuelIT for skipped shards (elastic#79490) Add other time accounting in HotThreads (elastic#79392) Add deprecation info API entries for deprecated monitoring settings (elastic#78799) Add note in breaking changes for nameid_format (elastic#77785) Use 'migration' instead of 'upgrade' in GET system feature migration status responses (elastic#79302) Upgrade lucene version 8b68bf60c98 (elastic#79461) Use Strings#EMPTY_ARRAY (elastic#79452) Quicker shared cache file preallocation (elastic#79447) [ML] Removing some code that's obsolete for 8.0 (elastic#79444) Ensure indexing_data CCR requests are compressed (elastic#79413) ...

The sort by change has been merged in 7.x now and therefore we should make 8.0 use the same BWC version. Relates to elastic#79392 and elastic#79507

The sort by change has been merged in 7.x now and therefore we should make 8.0 use the same BWC version. Relates to #79392 and #79507 Co-authored-by: Nhat Nguyen <[email protected]>

The sort by change has been merged in 7.x now and therefore we should make 8.0 use the same BWC version. Relates to elastic#79392 and elastic#79507 Co-authored-by: Nhat Nguyen <[email protected]>

Nikola Grcevski added 10 commits October 14, 2021 15:53

Improve sampling of wait/blocked.

a434a16

Small refactor.

75d7e85

Refactor.

d6e5947

Add sort everywhere.

d9d746c

Make monitoring part of bootstrap

16520a2

Update tests and remove security setting.

22c3be8

Make code clearer.

423ad61

Fix style and tests.

ec7848e

Implement comments from Ryan.

5dd7579

elasticsearchmachine added the v8.0.0 label Oct 18, 2021

Undo edit.

1417916

grcevski commented Oct 18, 2021

View reviewed changes

Merge branch 'master' into feature/hot_threads_other

4bc05a0

grcevski commented Oct 18, 2021

View reviewed changes

grcevski added :Core/Infra/Core Core issues without another label >enhancement auto-backport Automatically create backport pull requests when merged Team:Core/Infra Meta label for core/infra team labels Oct 18, 2021

grcevski added the v7.16.0 label Oct 18, 2021

grcevski commented Oct 18, 2021

View reviewed changes

grcevski requested a review from rjernst October 18, 2021 20:04

elasticmachine and others added 4 commits October 19, 2021 07:53

Merge branch 'master' into feature/hot_threads_other

3dcec18

Fix test

9eb0804

Change version from static to straight constant.

f06b946

Merge branch 'feature/hot_threads_other' of github.com:grcevski/elast…

25ab3d7

…icsearch into feature/hot_threads_other

grcevski commented Oct 19, 2021

View reviewed changes

rjernst approved these changes Oct 19, 2021

View reviewed changes

Apply changes as per review.

c1c57d6

grcevski changed the title ~~Feature/hot threads other~~ Add other time accounting in HotThreads Oct 19, 2021

grcevski merged commit b6439c5 into elastic:master Oct 19, 2021

grcevski deleted the feature/hot_threads_other branch October 19, 2021 17:47

grcevski added a commit to grcevski/elasticsearch that referenced this pull request Oct 19, 2021

Add other time accounting in HotThreads

51a0c5b

Backport of elastic#79392

grcevski mentioned this pull request Oct 19, 2021

[7.x] Add other time accounting in HotThreads(#79392) #79507

Merged

grcevski added a commit that referenced this pull request Oct 19, 2021

Add other time accounting in HotThreads (#79507)

6e44c5e

This PR introduces the concept of 'other' time in the HotThreads report. Backport of #79392

grcevski pushed a commit to grcevski/elasticsearch that referenced this pull request Oct 20, 2021

Reduce BWC version for HotThreads.sort

f3a93d5

The sort by change has been merged in 7.x now and therefore we should make 8.0 use the same BWC version. Relates to elastic#79392 and elastic#79507

grcevski mentioned this pull request Oct 20, 2021

Reduce BWC version for HotThreads.sort #79583

Merged

grcevski mentioned this pull request Oct 26, 2021

[7.x] Reduce BWC version for HotThreads.sort (#79583) #79864

Merged

jakelandis added v8.0.0-beta1 and removed v8.0.0 labels Oct 27, 2021

		@@ -32,6 +33,10 @@

		public class HotThreadsTests extends ESTestCase {

		private long nanosHelper(long millis) {

		assertThat(exception.getMessage(), equalTo("thread allocated memory is not supported on this JDK"));

		// making sure CPU type was not affected when isThreadAllocatedMemorySupported() == false

		@@ -20,8 +21,11 @@

		public class NodesHotThreadsRequest extends BaseNodesRequest<NodesHotThreadsRequest> {

		private static final Version SORT_SUPPORTED_VERSION = Version.V_8_0_0;

Add other time accounting in HotThreads #79392

Add other time accounting in HotThreads #79392

Conversation

grcevski commented Oct 18, 2021

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

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

elasticmachine commented Oct 18, 2021

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

grcevski commented Oct 19, 2021

Choose a reason for hiding this comment

rjernst 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

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

elasticsearchmachine commented Oct 19, 2021

💔 Backport failed