Skip to content

Commit

Permalink
[JENKINS-38692] Add extra logging to help diagnosing Thread spike. (#116
Browse files Browse the repository at this point in the history 
)

Add extra logging statements to try and get to the root cause
of the IOHub thread spike.
  • Loading branch information
@jtnord @oleg-nenashev
jtnord authored and oleg-nenashev committed Oct 25, 2016
1 parent 0fc87e4 commit 46c72a5
Show file tree
Hide file tree
Showing 2 changed files with 54 additions and 4 deletions.
40 changes: 37 additions & 3 deletions src/main/java/org/jenkinsci/remoting/protocol/IOHub.java
View file
Expand Up @@ -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();
}
Expand All @@ -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();
}
Expand All @@ -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();
}
Expand All @@ -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();
}
Expand Down Expand Up @@ -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<DelayedRunnable> scheduledWork = new ArrayList<DelayedRunnable>();
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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;
Expand Down
18 changes: 17 additions & 1 deletion src/main/java/org/jenkinsci/remoting/protocol/impl/NIONetworkLayer.java
View file
Expand Up @@ -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) {
recvLock.lock();
try {
Expand Down Expand Up @@ -202,9 +206,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;
}
Expand Down Expand Up @@ -238,6 +251,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());
}
}

/**
Expand Down

0 comments on commit 46c72a5

Please sign in to comment.