浏览代码

Mention network handler logging in docs (#100118)

Mentions the `InboundHandler` (and `OutboundHandler`) as potential
sources of useful log messages when tracking down a network threading
bug.
David Turner 2 年之前
父节点
当前提交
5dff56a00e

+ 9 - 0
docs/reference/modules/network/threading.asciidoc

@@ -107,3 +107,12 @@ However, this API itself sends network messages so may not work correctly if
 the `transport_worker` threads are too busy. It is more reliable to use
 `jstack` to obtain stack dumps or use Java Flight Recorder to obtain a
 profiling trace. These tools are independent of any work the JVM is performing.
+
+It may also be possible to identify some reasons for delays from the server
+logs, particularly looking at warnings from
+`org.elasticsearch.transport.InboundHandler` and
+`org.elasticsearch.transport.OutboundHandler`. Warnings about long processing
+times from the `InboundHandler` are particularly indicative of incorrect
+threading behaviour, whereas the transmission time reported by the
+`OutboundHandler` includes time spent waiting for network congestion and the
+`transport_worker` thread is free to do other work during this time.

+ 3 - 1
docs/reference/troubleshooting/network-timeouts.asciidoc

@@ -47,5 +47,7 @@ since it doesn't require any JVM threads.
 The threads involved in discovery and cluster membership are mainly
 `transport_worker` and `cluster_coordination` threads, for which there should
 never be a long wait. There may also be evidence of long waits for threads in
-the {es} logs. See <<modules-network-threading-model>> for more information.
+the {es} logs, particularly looking at warning logs from
+`org.elasticsearch.transport.InboundHandler`. See
+<<modules-network-threading-model>> for more information.
 end::troubleshooting-network-timeouts-threads[]

+ 9 - 13
server/src/test/java/org/elasticsearch/transport/InboundHandlerTests.java

@@ -238,7 +238,7 @@ public class InboundHandlerTests extends ESTestCase {
         mockAppender.addExpectation(
             new MockLogAppender.SeenEventExpectation(
                 "expected message",
-                InboundHandler.class.getCanonicalName(),
+                EXPECTED_LOGGER_NAME,
                 Level.WARN,
                 "error processing handshake version"
             )
@@ -275,6 +275,12 @@ public class InboundHandlerTests extends ESTestCase {
         }
     }
 
+    /**
+     * This logger is mentioned in the docs by name, so we cannot rename it without adjusting the docs. Thus we fix the expected logger
+     * name in this string constant rather than using {@code InboundHandler.class.getCanonicalName()}.
+     */
+    private static final String EXPECTED_LOGGER_NAME = "org.elasticsearch.transport.InboundHandler";
+
     public void testLogsSlowInboundProcessing() throws Exception {
         final MockLogAppender mockAppender = new MockLogAppender();
         mockAppender.start();
@@ -286,12 +292,7 @@ public class InboundHandlerTests extends ESTestCase {
             final TransportVersion remoteVersion = TransportVersion.current();
 
             mockAppender.addExpectation(
-                new MockLogAppender.SeenEventExpectation(
-                    "expected slow request",
-                    InboundHandler.class.getCanonicalName(),
-                    Level.WARN,
-                    "handling request "
-                )
+                new MockLogAppender.SeenEventExpectation("expected slow request", EXPECTED_LOGGER_NAME, Level.WARN, "handling request ")
             );
 
             final long requestId = randomNonNegativeLong();
@@ -318,12 +319,7 @@ public class InboundHandlerTests extends ESTestCase {
             mockAppender.assertAllExpectationsMatched();
 
             mockAppender.addExpectation(
-                new MockLogAppender.SeenEventExpectation(
-                    "expected slow response",
-                    InboundHandler.class.getCanonicalName(),
-                    Level.WARN,
-                    "handling response "
-                )
+                new MockLogAppender.SeenEventExpectation("expected slow response", EXPECTED_LOGGER_NAME, Level.WARN, "handling response ")
             );
 
             final long responseId = randomNonNegativeLong();

+ 7 - 6
server/src/test/java/org/elasticsearch/transport/OutboundHandlerTests.java

@@ -317,16 +317,17 @@ public class OutboundHandlerTests extends ESTestCase {
         assertEquals("header_value", header.getHeaders().v1().get("header"));
     }
 
+    /**
+     * This logger is mentioned in the docs by name, so we cannot rename it without adjusting the docs. Thus we fix the expected logger
+     * name in this string constant rather than using {@code OutboundHandler.class.getCanonicalName()}.
+     */
+    private static final String EXPECTED_LOGGER_NAME = "org.elasticsearch.transport.OutboundHandler";
+
     public void testSlowLogOutboundMessage() throws Exception {
         final MockLogAppender mockAppender = new MockLogAppender();
         mockAppender.start();
         mockAppender.addExpectation(
-            new MockLogAppender.SeenEventExpectation(
-                "expected message",
-                OutboundHandler.class.getCanonicalName(),
-                Level.WARN,
-                "sending transport message "
-            )
+            new MockLogAppender.SeenEventExpectation("expected message", EXPECTED_LOGGER_NAME, Level.WARN, "sending transport message ")
         );
         final Logger outboundHandlerLogger = LogManager.getLogger(OutboundHandler.class);
         Loggers.addAppender(outboundHandlerLogger, mockAppender);