Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[JENKINS-38692] Add extra logging to help diagnosing Thread spike. #116

Merged
merged 2 commits into from
Oct 25, 2016
Merged

[JENKINS-38692] Add extra logging to help diagnosing Thread spike. #116

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
961cb72
[JENKINS-38692] Add extra logging to help diagnosing Thread spike.
jtnord Oct 6, 2016
af5c49e
Merge remote-tracking branch 'origin/master' into JENKINS-38692
jtnord Oct 6, 2016
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
40 changes: 37 additions & 3 deletions src/main/java/org/jenkinsci/remoting/protocol/IOHub.java
View file
Open in desktop
Original file line number Diff line number Diff line change
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)) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I thought you were going to pull this out to a class level constant initialized on classloading so that hotspot can reduce to no-op

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wouldn't have added the if here. It's adding verbosity for no reason in that case. I suppose you added that because of the TODO below...

Copy link
Member Author

@jtnord jtnord Oct 24, 2016 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@stephenc so the performance without inlining didn't seem to bad - and if we leave it as is then you can use the standard Jenkins UI (or JMX for agents) to change the logging level

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I suppose you added that because of the TODO below...

yes - easier to do it now and know the performance hit - also prevents someone forgetting to do it later.

// 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)) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

same

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

test saves auto-boxing and GC churn

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
Open in desktop
Original file line number Diff line number Diff line change
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) {
ByteBuffer recv = acquire();
recvLock.lock();
Expand Down Expand Up @@ -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;
}
Expand Down Expand Up @@ -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());
}
}

/**
Expand Down