java - Why does select() consume so much CPU time in my program?

Question

I have several Java applications that use MINA, and all of them use 20 MINA threads. One application serves around 10,000 concurrent connections, that are usually idle but receive input sometimes. 20 is likely a reasonable threadcount for that application, although I haven't exactly profiled it (which this question is getting at). Another application serves only around 15 connections at a time but initiates the IO work so they are very busy, and has 20 MINA threads anyway, which is obviously too many.

The thing that's strange to me is both applications always devote about 30%, sometimes as high as 60%, of their CPU time into MINA's select() method, profiled in VisualVM. The call stack looks like this:

java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:228)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:81)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
- locked <40ca5d54> (a sun.nio.ch.Util$2)
- locked <24649fe8> (a java.util.Collections$UnmodifiableSet)
- locked <3fae9662> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:72)
at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1093)
at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:722)

It seems to be based in a busy poll, which sounds really wrong to me.

Should I be worried when I see the number that high? What causes this? Is it something I need to optimize out or is it more akin to a sleep or idle routine? If it's more like a sleep routine is it somehow scheduled to be lower priority than other CPU work?

Update: this thread seems to be the same issue. I followed its advice, and am now running Java 1.7.0_45, but I am still seeing select taking as high as 90% of CPU time in an application with 10k connections.

We are using MINA 2.0.4, which means this relevant bug is fixed.

Answer 1

Unfortunately, this is wrong interpretation of the numbers.

I've faced this situation many times (and ask a question on stackoverflow too).

The main reason, is VisualVM doesn't show correct CPU time. It showing percentage of the thread time in RUNNING state. But from documentation on Thread.State:

Thread state for a runnable thread. A thread in the runnable state is executing in the Java virtual machine but it may be waiting for other resources from the operating system such as processor.

This is exactly what's going on. Actually, thread is blocked inside OS epoll_wait() call. On Linux box there are several ways you can confirm it's the case.

strace'ing thread

$ strace -tttT -f -p [thread-id]

Thread id could be obtained from jstack output:

$ jstack [java-pid]
[...]
"Netty Builtin Server 1" #17 prio=5 os_prio=31 tid=0x00000001013dd800 nid=0xe12f runnable [0x0000700001fe4000]
  java.lang.Thread.State: RUNNABLE
  at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
  at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:198)
[...]

in this case thread id is 0xe12f (should be converted to decimal). You will see the most of the time thread will be in epoll_wait() call.

pidstating thread

$ pidstat -tu -p [java-pid] | grep [thread pid]

you will see low system as well as user CPU time by this thread, meaning it doesn't consume CPU.

polling thread state using ps

$ ps -eL -o pid,tid,state | grep [thread-id]

you will see most of the time thread in state S or Sl (interruptible sleep) instead of R (runnable).

In the end you should not worrying about that if there are no operational issues with the service.