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

jtnord · 2016-10-06T11:52:37Z

JENKINS-38692 Add extra logging statements to try and get to the root cause
of the IOHub thread spike.

@reviewbybees esp @stephenc

Add extra logging statements to try and get to the root cause of the IOHub thread spike.

jtnord · 2016-10-06T11:53:21Z

pending running through the stress test benchmark to check for performance regressions.

jtnord · 2016-10-06T12:39:20Z

Stress test results
Fix uses more RAM, but has a lower VM load.

stephenc · 2016-10-06T14:22:30Z

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)) {


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

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...

@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

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.

stephenc · 2016-10-06T14:39:47Z

Single measurement results

agent-load-test --protocol JNLP4-plaintext --warmup 60 --collect 180 on OS-X, java version "1.8.0_102"

CPU load before: 1.53
CPU load after: 1.49

Avg Memory before: 195592±43263
Avg Memory after: 190434±41279

No significant difference observed... I'll need to collect a few more runs to get some measure on CPU load effects

oleg-nenashev · 2016-10-09T22:10:52Z

I think this PR is fine. More diagnostics rarely hurts, and additional condition check should not cause a significant performance degradation. So 👍 form me. BTW, it's going into remoting 3.1+ IMHO

amuniz · 2016-10-10T09:41:35Z

👍

oleg-nenashev · 2016-10-14T06:48:08Z

Retriggering

batmat

🐝

batmat · 2016-10-15T14:00:23Z

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)) {


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...

batmat · 2016-10-15T14:01:44Z

src/main/java/org/jenkinsci/remoting/protocol/IOHub.java

@@ -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)) {


test saves auto-boxing and GC churn

stephenc · 2016-10-15T15:20:09Z

@batmat those if statements are critical for performance as this is hot code and they avoid constructing the new Object[]

batmat · 2016-10-15T15:56:54Z

@stephenc my comment wasn't blindly targeting all ifs. I'm aware of what you say. The ones I commented on weren't constructing objects. Most here actually currently only pass references and don't construct anything.

stephenc · 2016-10-15T17:38:18Z

Still having to set up the stack frame to pass through... the testing I did on a few of these showed a negative impact where the if was removed... there was negligible difference vs where I moved the LOGGER.isLoggable(Level.FINEST) to a class level final boolean though

jtnord · 2016-10-24T14:19:32Z

@reviewbybees done - @oleg-nenashev over to you.

oleg-nenashev · 2016-10-24T14:28:18Z

is it still WiP? I doubt

The change introduces one serious bugfix (JENKINS-39596) and a bunch of various diagnostics improvements. Bugfixes: * [JENKINS-39596](https://issues.jenkins-ci.org/browse/JENKINS-39596) - Jenkins URL in `hudson.remoting.Engine` was always `null` since `3.0`. It was causing connection failures of Jenkins JNLP agents when using Java Web Start. ([PR jenkinsci#131](jenkinsci/remoting#131)) * [JENKINS-39617](https://issues.jenkins-ci.org/browse/JENKINS-39617) - `hudson.remoting.Engine` was failing to establish connection if one of the URLs parameter in parameters was malformed. ([PR jenkinsci#131](jenkinsci/remoting#131)) Improvements: * [JENKINS-39150](https://issues.jenkins-ci.org/browse/JENKINS-39150) - Add logic for dumping diagnostics across all the channels. ([PR jenkinsci#122](jenkinsci/remoting#122), [PR jenkinsci#125](jenkinsci/remoting#125)) * [JENKINS-39543](https://issues.jenkins-ci.org/browse/JENKINS-39543) - Improve the caller/callee correlation diagnostics in thread dumps. ([PR jenkinsci#119](jenkinsci/remoting#119)) * [JENKINS-39290](https://issues.jenkins-ci.org/browse/JENKINS-39290) - Add the `org.jenkinsci.remoting.nio.NioChannelHub.disabled` flag for disabling NIO (mostly for debugging purposes). ([PR jenkinsci#123](jenkinsci/remoting#123)) * [JENKINS-38692](https://issues.jenkins-ci.org/browse/JENKINS-38692) - Add extra logging to help diagnosing `IOHub` Thread spikes. ([PR #116](jenkinsci/remoting#116)) * [JENKINS-39289](https://issues.jenkins-ci.org/browse/JENKINS-39289) - When a proxy fails, report what caused the channel to go down. ([PR jenkinsci#128](jenkinsci/remoting#128))

The change introduces one serious bugfix (JENKINS-39596) and a bunch of various diagnostics improvements. Bugfixes: * [JENKINS-39596](https://issues.jenkins-ci.org/browse/JENKINS-39596) - Jenkins URL in `hudson.remoting.Engine` was always `null` since `3.0`. It was causing connection failures of Jenkins JNLP agents when using Java Web Start. ([PR #131](jenkinsci/remoting#131)) * [JENKINS-39617](https://issues.jenkins-ci.org/browse/JENKINS-39617) - `hudson.remoting.Engine` was failing to establish connection if one of the URLs parameter in parameters was malformed. ([PR #131](jenkinsci/remoting#131)) Improvements: * [JENKINS-39150](https://issues.jenkins-ci.org/browse/JENKINS-39150) - Add logic for dumping diagnostics across all the channels. ([PR #122](jenkinsci/remoting#122), [PR #125](jenkinsci/remoting#125)) * [JENKINS-39543](https://issues.jenkins-ci.org/browse/JENKINS-39543) - Improve the caller/callee correlation diagnostics in thread dumps. ([PR #119](jenkinsci/remoting#119)) * [JENKINS-39290](https://issues.jenkins-ci.org/browse/JENKINS-39290) - Add the `org.jenkinsci.remoting.nio.NioChannelHub.disabled` flag for disabling NIO (mostly for debugging purposes). ([PR #123](jenkinsci/remoting#123)) * [JENKINS-38692](https://issues.jenkins-ci.org/browse/JENKINS-38692) - Add extra logging to help diagnosing `IOHub` Thread spikes. ([PR #116](jenkinsci/remoting#116)) * [JENKINS-39289](https://issues.jenkins-ci.org/browse/JENKINS-39289) - When a proxy fails, report what caused the channel to go down. ([PR #128](jenkinsci/remoting#128))

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

961cb72

Add extra logging statements to try and get to the root cause of the IOHub thread spike.

jtnord added the work-in-progress label Oct 6, 2016

Merge remote-tracking branch 'origin/master' into JENKINS-38692

af5c49e

stephenc reviewed Oct 6, 2016

View reviewed changes

oleg-nenashev closed this Oct 14, 2016

oleg-nenashev reopened this Oct 14, 2016

batmat approved these changes Oct 15, 2016

View reviewed changes

jtnord removed the work-in-progress label Oct 25, 2016

oleg-nenashev merged commit 46c72a5 into jenkinsci:master Oct 25, 2016

oleg-nenashev mentioned this pull request Nov 9, 2016

Update remoting to 2.31 in the Jenkins core jenkinsci/jenkins#2628

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

jtnord commented Oct 6, 2016

jtnord commented Oct 6, 2016

jtnord commented Oct 6, 2016

stephenc Oct 6, 2016

batmat Oct 15, 2016

jtnord Oct 24, 2016 •

edited

jtnord Oct 25, 2016

stephenc commented Oct 6, 2016

oleg-nenashev commented Oct 9, 2016

amuniz commented Oct 10, 2016

oleg-nenashev commented Oct 14, 2016

batmat left a comment

batmat Oct 15, 2016

batmat Oct 15, 2016

jtnord Oct 25, 2016

stephenc commented Oct 15, 2016

batmat commented Oct 15, 2016 •

edited

stephenc commented Oct 15, 2016

jtnord commented Oct 24, 2016

oleg-nenashev commented Oct 24, 2016

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

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

Conversation

jtnord commented Oct 6, 2016

jtnord commented Oct 6, 2016

jtnord commented Oct 6, 2016

stephenc Oct 6, 2016

Choose a reason for hiding this comment

batmat Oct 15, 2016

Choose a reason for hiding this comment

jtnord Oct 24, 2016 • edited

Choose a reason for hiding this comment

jtnord Oct 25, 2016

Choose a reason for hiding this comment

stephenc commented Oct 6, 2016

oleg-nenashev commented Oct 9, 2016

amuniz commented Oct 10, 2016

oleg-nenashev commented Oct 14, 2016

batmat left a comment

Choose a reason for hiding this comment

batmat Oct 15, 2016

Choose a reason for hiding this comment

batmat Oct 15, 2016

Choose a reason for hiding this comment

jtnord Oct 25, 2016

Choose a reason for hiding this comment

stephenc commented Oct 15, 2016

batmat commented Oct 15, 2016 • edited

stephenc commented Oct 15, 2016

jtnord commented Oct 24, 2016

oleg-nenashev commented Oct 24, 2016

jtnord Oct 24, 2016 •

edited

batmat commented Oct 15, 2016 •

edited