Netty 4: NioEventLoop rebuild selector too often

Question

In the log file at the TRACE level for Netty I have such situation:

09:22:11,772 [DEBUG main       .logging.InternalLoggerFactory] Using Log4J as the default logging framework
09:22:11,780 [DEBUG main       til.internal.PlatformDependent] UID: 1000
09:22:11,780 [DEBUG main       til.internal.PlatformDependent] Java version: 7
09:22:11,781 [DEBUG main       til.internal.PlatformDependent] -Dio.netty.noUnsafe: false
09:22:11,783 [DEBUG main       il.internal.PlatformDependent0] java.nio.ByteBuffer.cleaner: available
09:22:11,783 [DEBUG main       il.internal.PlatformDependent0] java.nio.Buffer.address: available
09:22:11,784 [DEBUG main       il.internal.PlatformDependent0] sun.misc.Unsafe.theUnsafe: available
09:22:11,784 [DEBUG main       il.internal.PlatformDependent0] sun.misc.Unsafe.copyMemory: available
09:22:11,784 [DEBUG main       il.internal.PlatformDependent0] java.nio.Bits.unaligned: true
09:22:11,784 [DEBUG main       til.internal.PlatformDependent] sun.misc.Unsafe: available
09:22:11,784 [DEBUG main       til.internal.PlatformDependent] -Dio.netty.noJavassist: false
09:22:11,840 [DEBUG main       til.internal.PlatformDependent] Javassist: available
09:22:11,841 [DEBUG main       til.internal.PlatformDependent] -Dio.netty.tmpdir: /tmp (java.io.tmpdir)
09:22:11,841 [DEBUG main       til.internal.PlatformDependent] -Dio.netty.bitMode: 64 (sun.arch.data.model)
09:22:11,841 [DEBUG main       til.internal.PlatformDependent] -Dio.netty.noPreferDirect: false
09:22:11,843 [DEBUG main       tTypeParameterMatcherGenerator] Generated: io.netty.util.internal.__matchers__.ru.concerteza.amber.pult2.message.MessageMatcher
09:22:11,872 [DEBUG main       nnel.MultithreadEventLoopGroup] -Dio.netty.eventLoopThreads: 8
09:22:11,899 [DEBUG main       netty.channel.nio.NioEventLoop] -Dio.netty.noKeySetOptimization: false
09:22:11,899 [DEBUG main       netty.channel.nio.NioEventLoop] -Dio.netty.selectorAutoRebuildThreshold: 512
09:22:11,902 [TRACE main       netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@d8f211f
09:22:11,903 [TRACE main       netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@2fc7812d
09:22:11,903 [TRACE main       netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@52f1c9dc
09:22:11,903 [TRACE main       netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@7ffbb50e
09:22:11,903 [TRACE main       netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@662bebc6
09:22:11,903 [TRACE main       netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@4d844891
09:22:11,903 [TRACE main       netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@27b84f59
09:22:11,903 [TRACE main       netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@3561706e
09:22:11,904 [TRACE main       netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@6e6d863f
09:22:11,905 [TRACE main       netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@5888cabc
09:22:11,905 [TRACE main       netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@7cb62a0c
09:22:11,905 [TRACE main       netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@1b82b9cb
09:22:11,905 [TRACE main       netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@2373cc89
09:22:11,905 [TRACE main       netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@779488e
09:22:11,905 [TRACE main       netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@2b8a6677
09:22:11,905 [TRACE main       netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@b4d24f6
09:22:11,966 [DEBUG main       etty.util.ResourceLeakDetector] -Dio.netty.leakDetectionLevel: simple
09:22:12,250 [DEBUG main       til.internal.ThreadLocalRandom] -Dio.netty.initialSeedUniquifier: 0x6c1182c32deadabe
09:22:12,260 [DEBUG main       .channel.ChannelOutboundBuffer] -Dio.netty.threadLocalDirectBufferSize: 65536
09:22:12,292 [DEBUG main       io.netty.buffer.ByteBufUtil   ] -Dio.netty.allocator.type: unpooled
09:22:12,294 [DEBUG main       io.netty.util.NetUtil         ] Loopback interface: lo
09:22:12,294 [DEBUG main       io.netty.util.NetUtil         ] Loopback address: /0:0:0:0:0:0:0:1%1 (primary)
09:22:12,294 [DEBUG main       io.netty.util.NetUtil         ] Loopback address: /127.0.0.1
09:22:12,295 [DEBUG main       io.netty.util.NetUtil         ] /proc/sys/net/core/somaxconn: 128
09:22:47,569 [WARN  pGroup-3-1 netty.channel.nio.NioEventLoop] Selector.select() returned prematurely 512 times in a row; rebuilding selector.
09:22:47,569 [TRACE pGroup-3-1 netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@5f72f8be
09:22:47,569 [INFO  pGroup-3-1 netty.channel.nio.NioEventLoop] Migrated 0 channel(s) to the new Selector.
09:22:47,576 [WARN  pGroup-3-1 netty.channel.nio.NioEventLoop] Selector.select() returned prematurely 512 times in a row; rebuilding selector.
09:22:47,576 [TRACE pGroup-3-1 netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@7528b2e6
09:22:47,576 [INFO  pGroup-3-1 netty.channel.nio.NioEventLoop] Migrated 0 channel(s) to the new Selector.
09:22:47,582 [WARN  pGroup-3-1 netty.channel.nio.NioEventLoop] Selector.select() returned prematurely 512 times in a row; rebuilding selector.
09:22:47,582 [TRACE pGroup-3-1 netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@42f95621
09:22:47,582 [INFO  pGroup-3-1 netty.channel.nio.NioEventLoop] Migrated 0 channel(s) to the new Selector.
09:22:47,588 [WARN  pGroup-3-1 netty.channel.nio.NioEventLoop] Selector.select() returned prematurely 512 times in a row; rebuilding selector.
09:22:47,588 [TRACE pGroup-3-1 netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@7f85b2e0
09:22:47,588 [INFO  pGroup-3-1 netty.channel.nio.NioEventLoop] Migrated 0 channel(s) to the new Selector.
09:22:47,594 [WARN  pGroup-3-1 netty.channel.nio.NioEventLoop] Selector.select() returned prematurely 512 times in a row; rebuilding selector.
09:22:47,594 [TRACE pGroup-3-1 netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@22a2d188
09:22:47,594 [INFO  pGroup-3-1 netty.channel.nio.NioEventLoop] Migrated 0 channel(s) to the new Selector.
09:22:47,600 [WARN  pGroup-3-1 netty.channel.nio.NioEventLoop] Selector.select() returned prematurely 512 times in a row; rebuilding selector.
09:22:47,600 [TRACE pGroup-3-1 netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@6f6a497b
09:22:47,600 [INFO  pGroup-3-1 netty.channel.nio.NioEventLoop] Migrated 0 channel(s) to the new Selector.
09:22:47,606 [WARN  pGroup-3-1 netty.channel.nio.NioEventLoop] Selector.select() returned prematurely 512 times in a row; rebuilding selector.
09:22:47,606 [TRACE pGroup-3-1 netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@2afe6362
09:22:47,606 [INFO  pGroup-3-1 netty.channel.nio.NioEventLoop] Migrated 0 channel(s) to the new Selector.
09:22:47,612 [WARN  pGroup-3-1 netty.channel.nio.NioEventLoop] Selector.select() returned prematurely 512 times in a row; rebuilding selector.
09:22:47,612 [TRACE pGroup-3-1 netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@232eccfb
09:22:47,612 [INFO  pGroup-3-1 netty.channel.nio.NioEventLoop] Migrated 0 channel(s) to the new Selector.
09:22:47,618 [WARN  pGroup-3-1 netty.channel.nio.NioEventLoop] Selector.select() returned prematurely 512 times in a row; rebuilding selector.
09:22:47,618 [TRACE pGroup-3-1 netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@559384c8
09:22:47,618 [INFO  pGroup-3-1 netty.channel.nio.NioEventLoop] Migrated 0 channel(s) to the new Selector.
09:22:47,631 [WARN  pGroup-3-1 netty.channel.nio.NioEventLoop] Selector.select() returned prematurely 512 times in a row; rebuilding selector.
09:22:47,632 [TRACE pGroup-3-1 netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@47f2925c
09:22:47,632 [INFO  pGroup-3-1 netty.channel.nio.NioEventLoop] Migrated 0 channel(s) to the new Selector.
09:22:47,638 [WARN  pGroup-3-1 netty.channel.nio.NioEventLoop] Selector.select() returned prematurely 512 times in a row; rebuilding selector.
09:22:47,639 [TRACE pGroup-3-1 netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@666faeb
09:22:47,639 [INFO  pGroup-3-1 netty.channel.nio.NioEventLoop] Migrated 0 channel(s) to the new Selector.
09:22:47,645 [WARN  pGroup-3-1 netty.channel.nio.NioEventLoop] Selector.select() returned prematurely 512 times in a row; rebuilding selector.
09:22:47,646 [TRACE pGroup-3-1 netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@52e35d95
09:22:47,646 [INFO  pGroup-3-1 netty.channel.nio.NioEventLoop] Migrated 0 channel(s) to the new Selector.
09:22:47,652 [WARN  pGroup-3-1 netty.channel.nio.NioEventLoop] Selector.select() returned prematurely 512 times in a row; rebuilding selector.
09:22:47,653 [TRACE pGroup-3-1 netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@4d150bb6
09:22:47,653 [INFO  pGroup-3-1 netty.channel.nio.NioEventLoop] Migrated 0 channel(s) to the new Selector.
09:22:47,659 [WARN  pGroup-3-1 netty.channel.nio.NioEventLoop] Selector.select() returned prematurely 512 times in a row; rebuilding selector.
09:22:47,659 [TRACE pGroup-3-1 netty.channel.nio.NioEventLoop] Instrumented an optimized java.util.Set into: sun.nio.ch.EPollSelectorImpl@20b40143
09:22:47,659 [INFO  pGroup-3-1 netty.channel.nio.NioEventLoop] Migrated 0 channel(s) to the new Selector.

And so on.

I have this after channel disconnected. This behavior happens only during some scenarios, not every time.

Where should I search for a problem? What does this often selector rebuildings mean?

Answer 1

The problem was that the worker thread from new NioEventLoopGroup() have been interrupted from the other thread.

See: bug report.

Answer 2

That sounds strange. Could you please open a bug report in our issue tracker and add informations like OS, java version, kernel version and also when this happens. Thanks!