Garbage being created from idle workers on 3.5.7.Final

On Java 1.6.0_u35, Windows 7 64-bit with 3.5.7.Final I see lots of garbage being generated (~17MB/minute with 16 workers) and churning from idle workers, immediately after startup before framework is actively used.

I don't observe this with 3.5.6.Final or 3.5.2.Final.

We're starting Netty as a client with a pretty standard setup like

        ChannelFactory factory = new NioClientSocketChannelFactory(
            Executors.newCachedThreadPool(),
            Executors.newCachedThreadPool());
    bootstrap = new ClientBootstrap(factory);

Any idea what's going on here?

Sorry for the formatting here, but here's an excerpt of a Yourkit allocation trace

Name            Recorded Objects  Size (bytes)
java.util.concurrent.ThreadPoolExecutor$Worker.run()    338335  12852080
  java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Runnable)  337818  12835328
    org.jboss.netty.util.internal.DeadLockProofWorker$1.run()   337725  12823856
      sun.nio.ch.SelectorImpl.select(long)  253434  9452216
        sun.nio.ch.SelectorImpl.lockAndDoSelect(long)   253434  9452216
          sun.nio.ch.WindowsSelectorImpl.doSelect(long) 253434  9452216
            sun.nio.ch.SelectorImpl.processDeregisterQueue()    167796  6711816
              java.util.HashMap$KeySet.iterator()   167795  6711800
              java.util.HashMap.keySet()    1   16
            sun.nio.ch.WindowsSelectorImpl.updateSelectedKeys() 85637   2740384
              java.util.AbstractList.iterator() 85637   2740384
            java.nio.channels.spi.AbstractSelector.begin()  1   16
      sun.nio.ch.Util$2.iterator()  84286   3371440
        java.util.HashSet.iterator()    84286   3371440
          java.util.HashMap$KeySet.iterator()   84286   3371440
            java.util.HashMap.newKeyIterator()  84286   3371440

[normanmaurer]

@voiceinsideyou could you upload the yourkit snapshot somewhere so I can have a look ?

Might be a bit difficult from within a heavily restricted corporate network, but first I'll have to try and replicate it in a simple test with no proprietary code - maybe that'll be useful in itself anyway. Will see if I can get some time to do that tomorrow.

[normanmaurer]

Thanks!

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

Am 12.09.2012 um 15:32 schrieb Chad notifications@github.com:

Might be a bit difficult from within a heavily restricted corporate network, but first I'll have to try and replicate it in a simple test with no proprietary code - maybe that'll be useful in itself anyway. Will see if I can get some time to do that tomorrow.

—
Reply to this email directly or view it on GitHub.

Here's trivial code which demonstrates it for me.

import java.util.concurrent.Executors;

import org.jboss.netty.bootstrap.ClientBootstrap;
import org.jboss.netty.channel.ChannelFactory;
import org.jboss.netty.channel.socket.nio.NioClientSocketChannelFactory;

public class NettyTest {

    public static void main(String... args) throws Exception {
        ChannelFactory factory = new NioClientSocketChannelFactory(
                        Executors.newCachedThreadPool(),
                        Executors.newCachedThreadPool());
        new ClientBootstrap(factory);

        System.out.println("Started Netty");

        Thread.sleep(1000000);

    }
}

Here's the log:

"C:\Program Files\Java\jdk1.6.0_35\bin\java" -server -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC -agentpath:C:\PROGRA~2\YOURKI~1.6\bin\win64\yjpagent.dll=alloceach=10,allocsizelimit=1048576,sampling,walltimespec=YJPQUOTED433a5c55736572735c6e626466736f695c2e796a705c636f6e6669675c2e77616c6c74696d65,noj2ee,onexit=snapshot,sessionname=NettyTest,profileruipath=YJPQUOTED433a5c50726f6772616d2046696c65732028783836295c596f75724b6974204a6176612050726f66696c657220392e352e365c62696e5c796a702e657865,ideport=51480 -Didea.launcher.port=7550 "-Didea.launcher.bin.path=C:\Program Files (x86)\JetBrains\IntelliJ IDEA 11.1\bin" -Dfile.encoding=windows-1252 -classpath "C:\Program Files\Java\jdk1.6.0_35\jre\lib\charsets.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\deploy.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\javaws.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\jce.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\jsse.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\management-agent.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\plugin.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\resources.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\rt.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\ext\dnsns.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\ext\localedata.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\ext\sunjce_provider.jar;C:\Working\dev\example_code\nettytest\target\classes;C:\Working\repo\io\netty\netty\3.5.7.Final\netty-3.5.7.Final.jar;C:\Program Files (x86)\JetBrains\IntelliJ IDEA 11.1\lib\idea_rt.jar" com.intellij.rt.execution.application.AppMain NettyTest
[YourKit Java Profiler 9.5.6] Loaded. Log file: C:\Users\xxxxxx\.yjp\log\7240.log
Started Netty
2012-09-13T15:05:00.758+0800: [GC [ParNew: 17024K->620K(19136K), 0.0114960 secs] 17024K->620K(83008K), 0.0115489 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 

Same behaviour with 1.7.0_u7 64-bit. Confirm that behaviour not seen under either Java version with Netty 3.5.6.Final.

[normanmaurer]

Thanks will start looking into this!

Am 13.09.2012 um 09:08 schrieb Chad notifications@github.com:

Here's trivial code which demonstrates it for me.

import java.util.concurrent.Executors;

import org.jboss.netty.bootstrap.ClientBootstrap;
import org.jboss.netty.channel.ChannelFactory;
import org.jboss.netty.channel.socket.nio.NioClientSocketChannelFactory;

public class NettyTest {

public static void main(String... args) throws Exception {
    ChannelFactory factory = new NioClientSocketChannelFactory(
                    Executors.newCachedThreadPool(),
                    Executors.newCachedThreadPool());
    new ClientBootstrap(factory);

    System.out.println("Started Netty");

    Thread.sleep(1000000);

}

}
Here's the log:

"C:\Program Files\Java\jdk1.6.0_35\bin\java" -server -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC -agentpath:C:\PROGRA2\YOURKI1.6\bin\win64\yjpagent.dll=alloceach=10,allocsizelimit=1048576,sampling,walltimespec=YJPQUOTED433a5c55736572735c6e626466736f695c2e796a705c636f6e6669675c2e77616c6c74696d65,noj2ee,onexit=snapshot,sessionname=NettyTest,profileruipath=YJPQUOTED433a5c50726f6772616d2046696c65732028783836295c596f75724b6974204a6176612050726f66696c657220392e352e365c62696e5c796a702e657865,ideport=51480 -Didea.launcher.port=7550 "-Didea.launcher.bin.path=C:\Program Files (x86)\JetBrains\IntelliJ IDEA 11.1\bin" -Dfile.encoding=windows-1252 -classpath "C:\Program Files\Java\jdk1.6.0_35\jre\lib\charsets.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\deploy.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\javaws.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\jce.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\jsse.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\management-agent.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\plugin.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\resources.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\rt.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\ext\dnsns.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\ext\localedata.jar;C:\Program Files\Java\jdk1.6.0_35\jre\lib\ext\sunjce_provider.jar;C:\Working\dev\example_code\nettytest\target\classes;C:\Working\repo\io\netty\netty\3.5.7.Final\netty-3.5.7.Final.jar;C:\Program Files (x86)\JetBrains\IntelliJ IDEA 11.1\lib\idea_rt.jar" com.intellij.rt.execution.application.AppMain NettyTest
[YourKit Java Profiler 9.5.6] Loaded. Log file: C:\Users\xxxxxx.yjp\log\7240.log
Started Netty
2012-09-13T15:05:00.758+0800: [GC [ParNew: 17024K->620K(19136K), 0.0114960 secs] 17024K->620K(83008K), 0.0115489 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
Same behaviour with 1.7.0_u7 64-bit. Confirm that behaviour not seen under either Java version with Netty 3.5.6.Final.

—
Reply to this email directly or view it on GitHub.

[normanmaurer]

@voiceinsideyou now I understand what you are refer too :) The change that "produce" this is that in 3.5.7.Final we start the Worker automaticly which we did not before. In earlier releases we started it in a lazy fashion which had other problems as we needed to have more synchronization in place. Anyway I think we can cut these "garbage" and still start it in a non-lazy fashion. Gimme a few minutes

[normanmaurer]

@voiceinsideyou could you grab the latest 3.5.8.Final-SNAPSHOT and see if its fix your problem:
https://repository-netty.forge.cloudbees.com/snapshot/io/netty/netty/3.5.8.Final-SNAPSHOT/

To be clear the "problem" was also in earlier releases of Netty but only showed up once you did the first "connect" with the client.

[normanmaurer]

@voiceinsideyou let me know if it works for you and if so I will close this issue

Ahh OK. Would the level of "garbage" creation have increased in 3.5.7.Final from previous releases?

I originally noticed this as our server was sitting there idling and I saw the GC regularly kicking in - I don't recall seeing that with previous Netty releases; even after the workers had been started/used for actual connections.

[normanmaurer]

@voiceinsideyou at least in the 3.5.x series it should be the same also before. I think in 3.3.x we was "shutdown" the worker if nothing was left to process but I would need to check if that is true. Anyway let me know if it fix your problem ;)

OK. We only moved to 3.5.x series 6 weeks ago (from 3.2.7.Final) so I may just not have noticed for one reason or another - and a bit of garbage is a small price to pay to address #240 in any case! Will take a look at the snapshot.

Doesn't seem to have changed things really. Still churning 5000 objects every few seconds with netty-3.5.8.Final-20120913.075429-3.jar.

Looks like it's just the sheer number of calls to SelectorUtil.select() from the AbstractNioWorker's run method... the garbage objects themselves are all produced inside WindowsSelectorImpl.doSelect() - they are iterators created by SelectorImpl.processDeregisterQueue() and WindowsSelectorImpl.updateSelectedKeys().