From 961cb7259ba7c10854bf9e2e6b64eac27f2bd3b0 Mon Sep 17 00:00:00 2001 From: James Nord Date: Thu, 6 Oct 2016 12:49:48 +0100 Subject: [PATCH] [JENKINS-38692] Add extra logging to help diagnosing Thread spike. Add extra logging statements to try and get to the root cause of the IOHub thread spike. --- .../jenkinsci/remoting/protocol/IOHub.java | 40 +++++++++++++++++-- .../protocol/impl/NIONetworkLayer.java | 18 ++++++++- 2 files changed, 54 insertions(+), 4 deletions(-) diff --git a/src/main/java/org/jenkinsci/remoting/protocol/IOHub.java b/src/main/java/org/jenkinsci/remoting/protocol/IOHub.java index 1c7cb3b1d..f93bbdf03 100644 --- a/src/main/java/org/jenkinsci/remoting/protocol/IOHub.java +++ b/src/main/java/org/jenkinsci/remoting/protocol/IOHub.java @@ -292,6 +292,10 @@ public final void removeInterestConnect(SelectionKey key) { * @param key the key. */ public final void addInterestRead(SelectionKey key) { + if (LOGGER.isLoggable(Level.FINEST)) { + // TODO probably want some more info about the key here... + LOGGER.log(Level.FINEST, "Scheduling adding OP_READ to {0}", key); + } interestOps.add(new InterestOps(key, SelectionKey.OP_READ, 0)); selector.wakeup(); } @@ -302,6 +306,10 @@ public final void addInterestRead(SelectionKey key) { * @param key the key. */ public final void removeInterestRead(SelectionKey key) { + if (LOGGER.isLoggable(Level.FINEST)) { + // TODO probably want some more info about the key here... + LOGGER.log(Level.FINEST, "Scheduling removing OP_READ to {0}", key); + } interestOps.add(new InterestOps(key, 0, SelectionKey.OP_READ)); selector.wakeup(); } @@ -312,6 +320,10 @@ public final void removeInterestRead(SelectionKey key) { * @param key the key. */ public final void addInterestWrite(SelectionKey key) { + if (LOGGER.isLoggable(Level.FINEST)) { + // TODO probably want some more info about the key here... + LOGGER.log(Level.FINEST, "Scheduling adding OP_WRITE to {0}", key); + } interestOps.add(new InterestOps(key, SelectionKey.OP_WRITE, 0)); selector.wakeup(); } @@ -322,6 +334,10 @@ public final void addInterestWrite(SelectionKey key) { * @param key the key. */ public final void removeInterestWrite(SelectionKey key) { + if (LOGGER.isLoggable(Level.FINEST)) { + // TODO probably want some more info about the key here... + LOGGER.log(Level.FINEST, "Scheduling removing OP_WRITE to {0}", key); + } interestOps.add(new InterestOps(key, 0, SelectionKey.OP_WRITE)); selector.wakeup(); } @@ -480,7 +496,11 @@ public final void run() { * Process the scheduled tasks list. */ private void processScheduledTasks() { - if (scheduledTasks.size() > 4) { + final int tasksWaiting = scheduledTasks.size(); + if (LOGGER.isLoggable(Level.FINEST)) { + LOGGER.log(Level.FINEST, "{0} scheduled tasks to process", tasksWaiting); + } + if (tasksWaiting > 4) { // DelayQueue.drainTo is more efficient than repeated polling // but we don't want to create the ArrayList every time the selector loops List scheduledWork = new ArrayList(); @@ -690,6 +710,14 @@ public void run() { final String oldName = workerThread.getName(); try { workerThread.setName("IOHub#" + _id + ": Worker[channel:" + key.channel() + "] / " + oldName); + if (LOGGER.isLoggable(Level.FINEST)) { + // TODO probably want some more info about the key here... + LOGGER.log(Level.FINEST, "Calling listener.ready({0}, {1}, {2}, {3}) for channel {4}", + new Object[] { (ops & SelectionKey.OP_ACCEPT) == SelectionKey.OP_ACCEPT, + (ops & SelectionKey.OP_CONNECT) == SelectionKey.OP_CONNECT, + (ops & SelectionKey.OP_READ) == SelectionKey.OP_READ, + (ops & SelectionKey.OP_WRITE) == SelectionKey.OP_WRITE, key.channel() }); + } listener.ready((ops & SelectionKey.OP_ACCEPT) == SelectionKey.OP_ACCEPT, (ops & SelectionKey.OP_CONNECT) == SelectionKey.OP_CONNECT, (ops & SelectionKey.OP_READ) == SelectionKey.OP_READ, @@ -742,11 +770,17 @@ private InterestOps(SelectionKey key, int add, int remove) { } /** - * Returns the desired {@link SelectionKey#interestOps()}. + * Returns {@code true} if the desired {@link SelectionKey#interestOps()} was potentially updated. + * This method will generally return {@code false} only if the {@link SelectionKey} is no longer valid when the request runs. * - * @return the desired {@link SelectionKey#interestOps()}. + * @return {@code true} if the desired {@link SelectionKey#interestOps()} was potentially modified. */ private boolean interestOps() { + if (LOGGER.isLoggable(Level.FINEST)) { + // TODO probably want some more info about the key here... + LOGGER.log(Level.FINEST, "updating interest ops &={0} |={1} on {2} with existing ops {3} on key {4}", + new Object[] { opsAnd, opsOr, key.channel(), key.interestOps(), key }); + } if (key.isValid()) { key.interestOps((key.interestOps() & opsAnd) | opsOr); return true; diff --git a/src/main/java/org/jenkinsci/remoting/protocol/impl/NIONetworkLayer.java b/src/main/java/org/jenkinsci/remoting/protocol/impl/NIONetworkLayer.java index 1fe913613..de4d4371a 100644 --- a/src/main/java/org/jenkinsci/remoting/protocol/impl/NIONetworkLayer.java +++ b/src/main/java/org/jenkinsci/remoting/protocol/impl/NIONetworkLayer.java @@ -123,6 +123,10 @@ public NIONetworkLayer(IOHub ioHub, ReadableByteChannel in, */ @Override public void ready(boolean accept, boolean connect, boolean read, boolean write) { + if (LOGGER.isLoggable(Level.FINEST)) { + LOGGER.log(Level.FINEST, "{0} - entering ready({1}, {2}, {3}, {4})", + new Object[] { Thread.currentThread().getName(), accept, connect, read, write }); + } if (read) { ByteBuffer recv = acquire(); recvLock.lock(); @@ -194,9 +198,18 @@ public void ready(boolean accept, boolean connect, boolean read, boolean write) sendQueue.get(send); sendHasRemaining = sendQueue.hasRemaining(); } + if (LOGGER.isLoggable(Level.FINEST)) { + LOGGER.log(Level.FINEST, "[{0}] sendHasRemaining - has remaining: {1}", + new Object[] { Thread.currentThread().getName(), sendHasRemaining }); + } send.flip(); try { - if (out.write(send) == -1) { + final int sentBytes = out.write(send); + if (LOGGER.isLoggable(Level.FINEST)) { + LOGGER.log(Level.FINEST, "[{0}] sentBytes - sent {1} bytes", + new Object[] { Thread.currentThread().getName(), sentBytes }); + } + if (sentBytes == -1) { sendKey.cancel(); return; } @@ -230,6 +243,9 @@ public void ready(boolean accept, boolean connect, boolean read, boolean write) release(send); } } + if (LOGGER.isLoggable(Level.FINEST)) { + LOGGER.log(Level.FINEST, "{0} - leaving ready(...)", Thread.currentThread().getName()); + } } /**