Repository: netty/netty
Issue: very high context switching when using netty to establish websocket connection in 3.5.7

The context switching on centos 5 has almost doubled when I switched from netty 3.5.3 to netty 3.5.7 for creating websocket connections.

Just upgrading netty jar caused context switches to jump from 2000 to 5000. Even 2000 were high especially when there was no websocket traffic and now it is just ridiculously high.


Issue comments:
In 3.5.3, the context switching was high in websocket client connections but in 3.5.7 the context switching is high for both server and client connections.

The main reason for I believe is lowering the select timeout from `500` to `10` milliseconds. @trustin / @normanmaurer, I think the solution of lowering it is problematic, since as explained here, and based on what I have seen, the overhead is quite big.

@kimchy what I not get is that @gauravsri says that it was not in 3.5.3... The lowering of the timeout was done before that. The problem with have the timeout high is that you will "delay" events if you are "lucky" enough, and so harm throughput. What you can do now is that you adjust it via the "org.jboss.netty.selectTimeout" property to match your need... Anyway we may want to think about to make a higher default value better "fit" the average user.

In 3.5.3, I only see high context switching when using it for client connections (@200-300 more context switches per second per client connection). In 3.5.7, the context switches are increasing for bother server and client connections.

This is definitely an issue for me as the issue was noted by a customer when they observed that the load average in 3.5.3 has suddenly increased by 4 on an idle system. I tried the latest version to see if that resolved the problem but it became even worse.

I will try by adjusting it using the property mentioned and let you know of my observations.

Changing the property to 500 doesn't seem to help. Following is output of vmstat when I launch with the new value.

There are no websocket connections at this time (only a websocket server listening on wss). As you can see the context switches still increases from 1500 to 3500.

   -Dorg.jboss.netty.selectTimeout=500  was set.

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0 1571720 122776 135748 224668    0    0     0   108 1043 1415  0  0 100  0  0
 0  0 1571720 122776 135748 224668    0    0     0     0 1016 1538  0  0 100  0  0
 1  0 1571720 122652 135748 224668    0    0     0     0 1012 1349  0  0 100  0  0
 0  0 1571720 122156 135748 224668    0    0     0     0 1012 1419  0  0 100  0  0
 1  0 1571720 113476 135748 224672    0    0     0    24 1017 1785 21  2 77  0  0
 4  0 1571720 102936 135748 224672    0    0     0   316 1066 1658 32  3 66  0  0
 1  0 1571720  82724 135748 224704    0    0     0     0 1021 2093 38  3 59  0  0
 1  0 1571720  78384 135748 224704    0    0     0     0 1019 1611 37  1 62  0  0
 1  0 1571720  75532 135748 224728    0    0     0     0 1017 1500 33  2 65  0  0
 0  0 1571720  70820 135748 224728    0    0     0   184 1054 4324 11  1 88  0  0
 1  0 1571720  70200 135748 224744    0    0     0   292 1042 4012  0  0 99  0  0
 0  0 1571720  69952 135748 224712   32    0    32    28 1029 4542  4  1 95  0  0
 0  0 1571720  69952 135748 224756    0    0     0     0 1012 3723  0  0 100  0  0
 1  0 1571720  70004 135748 224756    0    0     0     0 1016 8358 18  2 80  0  0
 1  0 1571720  69988 135748 224756    0    0     0   132 1036 5112  5  0 94  0  0
 1  0 1571720  69988 135748 224756    0    0     0     0 1011 3852  5  0 94  0  0
 0  0 1571720  69616 135748 224756    0    0     0   228 1048 3989  0  0 99  0  0
 0  0 1571720  69616 135748 224756    0    0     0     0 1015 3701  0  0 100  0  0
 0  0 1571720  67912 135748 224756    0    0     0     0 1014 3691  3  1 96  0  0
 1  0 1571720  67912 135748 224756    0    0     0     0 1015 3412  0  0 100  0  0
 2  0 1571720  68904 135748 224756    0    0     0     0 1013 3323  0  0 100  0  0
 3  0 1571720  68904 135748 224756    0    0     0   188 1038 3373  0  0 100  0  0
 1  0 1571720  68936 135748 224760    0    0     0     0 1013 3456  0  0 100  0  0
 0  0 1571720  69060 135748 224760    0    0     0     0 1015 3740  0  0 99  0  0
 2  0 1571720  69060 135748 224760    0    0     0    12 1027 3619  0  0 100  0  0
 0  0 1571720  69060 135748 224760    0    0     0     0 1014 3935  1  0 99  0  0
 0  0 1571720  69084 135748 224760    0    0     0   204 1038 3687  0  0 100  0  0
 0  0 1571720  69084 135748 224760    0    0     0     0 1019 3531  0  0 100  0  0
 1  0 1571720  69332 135748 224760    0    0     0     0 1015 3549  0  0 99  0  0
 1  0 1571720  69212 135748 224760    0    0     0    24 1025 8637 19  2 80  0  0
 0  0 1571720  69212 135748 224764    0    0     0     0 1016 4679  2  0 97  0  0
 0  0 1571720  69212 135756 224756    0    0     0    96 1035 3861  0  0 100  0  0
 1  0 1571720  69212 135756 224764    0    0     0     0 1016 3489  1  0 99  0  0
 0  0 1571720  69212 135756 224764    0    0     0     0 1013 3486  0  1 99  0  0
 0  0 1571720  69244 135756 224764    0    0     0    12 1018 3501  0  0 100  0  0
 1  0 1571720  69196 135756 224764    0    0     0     0 1013 9309 21  2 77  0  0
 0  0 1571720  69196 135764 224768    0    0     0   204 1035 3675  0  0 100  0  0
 0  0 1571720  69196 135764 224768    0    0     0     0 1011 3417  0  0 100  0  0
 0  0 1571720  69196 135764 224768    0    0     0     0 1014 3614  0  0 99  0  0
 0  0 1571720  69196 135764 224768    0    0     0    56 1022 3798  1  0 99  0  0
 1  1 1571720  68576 135764 224768    0    0     0   140 1014 3504  0  0 100  0  0

I will see if I can find the cause of this..

Can you share your code which you use to setup the ChannelPipeline etc ? It would be even better if you could submit a simple "app" that shows the problem ..

Am 15.09.2012 um 16:37 schrieb gauravsri notifications@github.com:

> Changing the property to 500 doesn't seem to help. Following is output of vmstat when I launch with the new value.
> 
> There are no websocket connections at this time (only a websocket server listening on wss). As you can see the context switches still increases from 1500 to 3500.
> 
> -Dorg.jboss.netty.selectTimeout=500 was set.
> 
> procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
> r b swpd free buff cache si so bi bo in cs us sy id wa st
> 0 0 1571720 122776 135748 224668 0 0 0 108 1043 1415 0 0 100 0 0
> 0 0 1571720 122776 135748 224668 0 0 0 0 1016 1538 0 0 100 0 0
> 1 0 1571720 122652 135748 224668 0 0 0 0 1012 1349 0 0 100 0 0
> 0 0 1571720 122156 135748 224668 0 0 0 0 1012 1419 0 0 100 0 0
> 1 0 1571720 113476 135748 224672 0 0 0 24 1017 1785 21 2 77 0 0
> 4 0 1571720 102936 135748 224672 0 0 0 316 1066 1658 32 3 66 0 0
> 1 0 1571720 82724 135748 224704 0 0 0 0 1021 2093 38 3 59 0 0
> 1 0 1571720 78384 135748 224704 0 0 0 0 1019 1611 37 1 62 0 0
> 1 0 1571720 75532 135748 224728 0 0 0 0 1017 1500 33 2 65 0 0
> 0 0 1571720 70820 135748 224728 0 0 0 184 1054 4324 11 1 88 0 0
> 1 0 1571720 70200 135748 224744 0 0 0 292 1042 4012 0 0 99 0 0
> 0 0 1571720 69952 135748 224712 32 0 32 28 1029 4542 4 1 95 0 0
> 0 0 1571720 69952 135748 224756 0 0 0 0 1012 3723 0 0 100 0 0
> 1 0 1571720 70004 135748 224756 0 0 0 0 1016 8358 18 2 80 0 0
> 1 0 1571720 69988 135748 224756 0 0 0 132 1036 5112 5 0 94 0 0
> 1 0 1571720 69988 135748 224756 0 0 0 0 1011 3852 5 0 94 0 0
> 0 0 1571720 69616 135748 224756 0 0 0 228 1048 3989 0 0 99 0 0
> 0 0 1571720 69616 135748 224756 0 0 0 0 1015 3701 0 0 100 0 0
> 0 0 1571720 67912 135748 224756 0 0 0 0 1014 3691 3 1 96 0 0
> 1 0 1571720 67912 135748 224756 0 0 0 0 1015 3412 0 0 100 0 0
> 2 0 1571720 68904 135748 224756 0 0 0 0 1013 3323 0 0 100 0 0
> 3 0 1571720 68904 135748 224756 0 0 0 188 1038 3373 0 0 100 0 0
> 1 0 1571720 68936 135748 224760 0 0 0 0 1013 3456 0 0 100 0 0
> 0 0 1571720 69060 135748 224760 0 0 0 0 1015 3740 0 0 99 0 0
> 2 0 1571720 69060 135748 224760 0 0 0 12 1027 3619 0 0 100 0 0
> 0 0 1571720 69060 135748 224760 0 0 0 0 1014 3935 1 0 99 0 0
> 0 0 1571720 69084 135748 224760 0 0 0 204 1038 3687 0 0 100 0 0
> 0 0 1571720 69084 135748 224760 0 0 0 0 1019 3531 0 0 100 0 0
> 1 0 1571720 69332 135748 224760 0 0 0 0 1015 3549 0 0 99 0 0
> 1 0 1571720 69212 135748 224760 0 0 0 24 1025 8637 19 2 80 0 0
> 0 0 1571720 69212 135748 224764 0 0 0 0 1016 4679 2 0 97 0 0
> 0 0 1571720 69212 135756 224756 0 0 0 96 1035 3861 0 0 100 0 0
> 1 0 1571720 69212 135756 224764 0 0 0 0 1016 3489 1 0 99 0 0
> 0 0 1571720 69212 135756 224764 0 0 0 0 1013 3486 0 1 99 0 0
> 0 0 1571720 69244 135756 224764 0 0 0 12 1018 3501 0 0 100 0 0
> 1 0 1571720 69196 135756 224764 0 0 0 0 1013 9309 21 2 77 0 0
> 0 0 1571720 69196 135764 224768 0 0 0 204 1035 3675 0 0 100 0 0
> 0 0 1571720 69196 135764 224768 0 0 0 0 1011 3417 0 0 100 0 0
> 0 0 1571720 69196 135764 224768 0 0 0 0 1014 3614 0 0 99 0 0
> 0 0 1571720 69196 135764 224768 0 0 0 56 1022 3798 1 0 99 0 0
> 1 1 1571720 68576 135764 224768 0 0 0 140 1014 3504 0 0 100 0 0
> 
> —
> Reply to this email directly or view it on GitHub.

I can create a sample App if needed.

As for setting up server pipeline, 

https://gist.github.com/3728640

@gauravsri thats all I need.. will investigate tomorrow ..

@gauravsri changing the system property helps a lot in my case.. I don't understand why it not helps you..

@kimchy @trustin do you think it worth it to change the timeout to  higher number by default and just let it get tuned by the "experience" folks ? I think we should better just ship with something that the "general" user can use and let the "experts" tune their setup.

What we also good do is have a select timeout of 500ms when the Worker is idle and when at least one channel is registered in the Worker we can adjust it to a smaller number. I think that could be done very easy and so we would safe a lot when idle.. WDYT ?

@gauravsri @kimchy @trustin just committed the "explained" idea in the context_switching branch.. WDYT ?

https://github.com/netty/netty/tree/context_switching

@normanmaurer Its a good step forward, I don't fully understand why the timeout was needed to be reduced. Is there a chance for an example of a case where smaller timeout helps? I bet it has to do with work that is not select driven, but what is it? Wondering if there is a way to try and solve it in a different manner?

@kimchy If I remember right it was driven by the handling of connection timeouts.. Let me recheck that..

@normanmaurer I can't understand why the system property is not working for me in 3.5.7. I am using the following arg in the command line but don't see any reduction in context switches.

/usr/j2se/bin/java -Dorg.jboss.netty.selectTimeout=500 

@normanmaurer I tried with the sample websocket server provided by netty and the context switches appear reduced with that code. I'll investigate into my application as to why it is showing more context switches with new netty library. 

@normanmaurer This issue is fixed with the configuration change. The problem in my App was related to the fact that System properties were being reloaded by the App and getting ignored by netty.

@normanmaurer This issue is fixed with the configuration change. The problem in my App was related to the fact that System properties were being reloaded by the App and getting ignored by netty.

Let us reopen this to find a better way to fix this out-of-the-box..

This should be fixed by #613


Pull request review comments:
newTimeout() accepts 'delay', not 'dead line'.

Doh.. Thanks

Sent from my iPhone. Excuse any typos....

Am 18.09.2012 um 08:28 schrieb Trustin Lee notifications@github.com:

> In src/main/java/org/jboss/netty/channel/socket/nio/NioClientSocketPipelineSink.java:
> 
> > @@ -231,10 +246,16 @@ void register(NioClientSocketChannel channel) {
> >                  boolean offered = registerTaskQueue.offer(registerTask);
> >                  assert offered;
> > 
> > ##              }
> > -            if (channel.connectDeadlineNanos > 0) {
> > -                if (!channel.isConnected()) {
> > -                    channel.timoutTimer = TIMER.newTimeout(wakeupTask,
> > -                            channel.connectDeadlineNanos, TimeUnit.NANOSECONDS);
> >   newTimeout() accepts 'delay', not 'dead line'.
> 
> —
> Reply to this email directly or view it on GitHub.


Patch that resolved the issue:
diff --git a/src/main/java/org/jboss/netty/channel/socket/nio/NioClientSocketChannel.java b/src/main/java/org/jboss/netty/channel/socket/nio/NioClientSocketChannel.java
index 2753f649730..b473c059289 100644
--- a/src/main/java/org/jboss/netty/channel/socket/nio/NioClientSocketChannel.java
+++ b/src/main/java/org/jboss/netty/channel/socket/nio/NioClientSocketChannel.java
@@ -27,6 +27,7 @@
 import org.jboss.netty.channel.ChannelSink;
 import org.jboss.netty.logging.InternalLogger;
 import org.jboss.netty.logging.InternalLoggerFactory;
+import org.jboss.netty.util.Timeout;
 
 final class NioClientSocketChannel extends NioSocketChannel {
 
@@ -71,6 +72,8 @@ private static SocketChannel newSocket() {
     // Does not need to be volatile as it's accessed by only one thread.
     long connectDeadlineNanos;
 
+    volatile Timeout timoutTimer;
+
     NioClientSocketChannel(
             ChannelFactory factory, ChannelPipeline pipeline,
             ChannelSink sink, NioWorker worker) {
diff --git a/src/main/java/org/jboss/netty/channel/socket/nio/NioClientSocketChannelFactory.java b/src/main/java/org/jboss/netty/channel/socket/nio/NioClientSocketChannelFactory.java
index 5b0800ee48d..4a75ab6f94d 100644
--- a/src/main/java/org/jboss/netty/channel/socket/nio/NioClientSocketChannelFactory.java
+++ b/src/main/java/org/jboss/netty/channel/socket/nio/NioClientSocketChannelFactory.java
@@ -26,6 +26,8 @@
 import org.jboss.netty.channel.socket.ClientSocketChannelFactory;
 import org.jboss.netty.channel.socket.SocketChannel;
 import org.jboss.netty.util.ExternalResourceReleasable;
+import org.jboss.netty.util.HashedWheelTimer;
+import org.jboss.netty.util.Timer;
 import org.jboss.netty.util.internal.ExecutorUtil;
 
 /**
@@ -86,6 +88,7 @@ public class NioClientSocketChannelFactory implements ClientSocketChannelFactory
     private final Executor bossExecutor;
     private final WorkerPool<NioWorker> workerPool;
     private final NioClientSocketPipelineSink sink;
+    private final Timer timer;
 
     /**
      * Creates a new {@link NioClientSocketChannelFactory} which uses {@link Executors#newCachedThreadPool()}
@@ -152,6 +155,12 @@ public NioClientSocketChannelFactory(
     public NioClientSocketChannelFactory(
             Executor bossExecutor, int bossCount,
             WorkerPool<NioWorker> workerPool) {
+        this(bossExecutor, bossCount, workerPool, new HashedWheelTimer());
+    }
+
+    public NioClientSocketChannelFactory(
+            Executor bossExecutor, int bossCount,
+            WorkerPool<NioWorker> workerPool, Timer timer) {
 
         if (bossExecutor == null) {
             throw new NullPointerException("bossExecutor");
@@ -168,8 +177,9 @@ public NioClientSocketChannelFactory(
 
         this.bossExecutor = bossExecutor;
         this.workerPool = workerPool;
+        this.timer = timer;
         sink = new NioClientSocketPipelineSink(
-                bossExecutor, bossCount, workerPool);
+                bossExecutor, bossCount, workerPool, timer);
     }
 
     public SocketChannel newChannel(ChannelPipeline pipeline) {
@@ -178,6 +188,7 @@ public SocketChannel newChannel(ChannelPipeline pipeline) {
 
     public void releaseExternalResources() {
         ExecutorUtil.terminate(bossExecutor);
+        timer.stop();
         if (workerPool instanceof ExternalResourceReleasable) {
             ((ExternalResourceReleasable) workerPool).releaseExternalResources();
         }
diff --git a/src/main/java/org/jboss/netty/channel/socket/nio/NioClientSocketPipelineSink.java b/src/main/java/org/jboss/netty/channel/socket/nio/NioClientSocketPipelineSink.java
index 12f08f4ae5a..3d79ce51fa5 100644
--- a/src/main/java/org/jboss/netty/channel/socket/nio/NioClientSocketPipelineSink.java
+++ b/src/main/java/org/jboss/netty/channel/socket/nio/NioClientSocketPipelineSink.java
@@ -32,6 +32,7 @@
 import java.util.concurrent.ConcurrentLinkedQueue;
 import java.util.concurrent.Executor;
 import java.util.concurrent.ExecutorService;
+import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.concurrent.atomic.AtomicInteger;
 
@@ -45,6 +46,10 @@
 import org.jboss.netty.channel.MessageEvent;
 import org.jboss.netty.logging.InternalLogger;
 import org.jboss.netty.logging.InternalLoggerFactory;
+import org.jboss.netty.util.HashedWheelTimer;
+import org.jboss.netty.util.Timeout;
+import org.jboss.netty.util.Timer;
+import org.jboss.netty.util.TimerTask;
 import org.jboss.netty.util.ThreadRenamingRunnable;
 import org.jboss.netty.util.internal.DeadLockProofWorker;
 
@@ -64,11 +69,13 @@ class NioClientSocketPipelineSink extends AbstractNioChannelSink {
 
     private final WorkerPool<NioWorker> workerPool;
 
+    private final Timer timer;
+
     NioClientSocketPipelineSink(
-            Executor bossExecutor, int bossCount, WorkerPool<NioWorker> workerPool) {
+            Executor bossExecutor, int bossCount, WorkerPool<NioWorker> workerPool, Timer timer) {
 
         this.bossExecutor = bossExecutor;
-
+        this.timer = timer;
         bosses = new Boss[bossCount];
         for (int i = 0; i < bosses.length; i ++) {
             bosses[i] = new Boss(i);
@@ -179,6 +186,15 @@ private final class Boss implements Runnable {
         private final Object startStopLock = new Object();
         private final Queue<Runnable> registerTaskQueue = new ConcurrentLinkedQueue<Runnable>();
         private final int subId;
+        private final TimerTask wakeupTask = new TimerTask() {
+            public void run(Timeout timeout) throws Exception {
+                if (selector != null) {
+                    if (wakenUp.compareAndSet(false, true)) {
+                        selector.wakeup();
+                    }
+                }
+            }
+        };
 
         Boss(int subId) {
             this.subId = subId;
@@ -231,10 +247,17 @@ void register(NioClientSocketChannel channel) {
                 boolean offered = registerTaskQueue.offer(registerTask);
                 assert offered;
             }
-
+            int timeout = channel.getConfig().getConnectTimeoutMillis();
+            if (timeout > 0) {
+                if (!channel.isConnected()) {
+                    channel.timoutTimer = timer.newTimeout(wakeupTask,
+                            timeout, TimeUnit.MILLISECONDS);
+                }
+            }
             if (wakenUp.compareAndSet(false, true)) {
                 selector.wakeup();
             }
+
         }
 
         public void run() {
@@ -339,10 +362,8 @@ public void run() {
 
                     // Handle connection timeout every 10 milliseconds approximately.
                     long currentTimeNanos = System.nanoTime();
-                    if (currentTimeNanos - lastConnectTimeoutCheckTimeNanos >= 10 * 1000000L) {
-                        lastConnectTimeoutCheckTimeNanos = currentTimeNanos;
-                        processConnectTimeout(selector.keys(), currentTimeNanos);
-                    }
+                    lastConnectTimeoutCheckTimeNanos = currentTimeNanos;
+                    processConnectTimeout(selector.keys(), currentTimeNanos);
 
                     // Exit the loop when there's nothing to handle.
                     // The shutdown flag is used to delay the shutdown of this
@@ -471,6 +492,9 @@ private void connect(SelectionKey k) throws IOException {
             NioClientSocketChannel ch = (NioClientSocketChannel) k.attachment();
             if (ch.channel.finishConnect()) {
                 k.cancel();
+                if (ch.timoutTimer != null) {
+                    ch.timoutTimer.cancel();
+                }
                 ch.worker.register(ch, ch.connectFuture);
             }
         }
diff --git a/src/main/java/org/jboss/netty/channel/socket/nio/SelectorUtil.java b/src/main/java/org/jboss/netty/channel/socket/nio/SelectorUtil.java
index a263f9e4b28..c2889e92c69 100644
--- a/src/main/java/org/jboss/netty/channel/socket/nio/SelectorUtil.java
+++ b/src/main/java/org/jboss/netty/channel/socket/nio/SelectorUtil.java
@@ -29,7 +29,7 @@ final class SelectorUtil {
         InternalLoggerFactory.getInstance(SelectorUtil.class);
 
     static final int DEFAULT_IO_THREADS = Runtime.getRuntime().availableProcessors() * 2;
-    static final long DEFAULT_SELECT_TIMEOUT = 10;
+    static final long DEFAULT_SELECT_TIMEOUT = 500;
     static final long SELECT_TIMEOUT =
             SystemPropertyUtil.getLong("org.jboss.netty.selectTimeout", DEFAULT_SELECT_TIMEOUT);
     static final long SELECT_TIMEOUT_NANOS = TimeUnit.MILLISECONDS.toNanos(SELECT_TIMEOUT);


Test patch: