How to analyze thread dumps in Java to minimize high CPU usage

Question

I'm trying to read text file and insert into database with Disruptor.

But I find that the CPU usage is too high (200%, according to top command).

I'm new to performance tuning and thread dump analysis. I don't know what's going wrong.

So I execute top -H and find the two highest threads (both are 99%), and find the thread dump:

"main" prio=10 tid=0x00007f54a4006800 nid=0x79ab runnable [0x00007f54a8340000]
   java.lang.Thread.State: RUNNABLE
    at java.lang.Thread.yield(Native Method)
    at com.lmax.disruptor.SingleProducerSequencer.next(SingleProducerSequencer.java:104)
    at com.lmax.disruptor.SingleProducerSequencer.next(SingleProducerSequencer.java:79)
    at com.lmax.disruptor.RingBuffer.next(RingBuffer.java:207)
    at com.xxx.xxx.connectivity.quickfixj.FixMessageReceiver.onMessage(FixMessageReceiver.java:105)
    at com.xxx.xxx.database.DatabaseService.start(DatabaseService.java:110)
    at com.xxx.xxx.database.DatabaseService.main(DatabaseService.java:168)


"pool-2-thread-1" prio=10 tid=0x00007f54a426d800 nid=0x79bc runnable [0x00007f5492a37000]
   java.lang.Thread.State: RUNNABLE
    at java.lang.Thread.yield(Native Method)
    at com.lmax.disruptor.SingleProducerSequencer.next(SingleProducerSequencer.java:104)
    at com.lmax.disruptor.SingleProducerSequencer.next(SingleProducerSequencer.java:79)
    at com.lmax.disruptor.RingBuffer.next(RingBuffer.java:207)
    at com.cimb.reporting.connectivity.jms.DatabaseEventHandler.publish2DbRingBuffer(DatabaseEventHandler.java:49)
    at com.xxx.xxx.connectivity.jms.DatabaseEventHandler.onEvent(DatabaseEventHandler.java:39)
    at com.xxx.xxx.connectivity.jms.DatabaseEventHandler.onEvent(DatabaseEventHandler.java:15)
    at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:133)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
    at java.lang.Thread.run(Thread.java:662)

Basically these two threads are going to publish data to Disruptor. I create Disruptor in this way:

Disruptor<TradeEvent> disruptor = new Disruptor<TradeEvent>(TradeEvent.TRADE_EVENT_FACTORY,
                properties.dbRingbufferSize(), Executors.newCachedThreadPool(),
                ProducerType.SINGLE, new BlockingWaitStrategy());

Please help me and analyze the thread dump to find the root cause of high CPU usage.

Answer 1

Faced exactly the same problem: 100% cpu usage on my machine Intel Core i3-3220 with 16GB memory with one broker (Xmx 2G), one client (Xmx2G) and without any message in a ringbuffer.

Quick profiling shows that Thread.yield() consumes about 70-80% of cpu.

It is turned out the YieldingWaitStrategy is not a proper strategy in my case. So in my case quick fix was to set the wait strategy into BlockingWaitStrategy:

Disruptor<MessageEvent> disruptor = new Disruptor<MessageEvent>(eventFactory, RING_BUFFER_SIZE, executor, ProducerType.SINGLE, new BlockingWaitStrategy());

---

UPDATE

JProfiler for YieldingWaitStrategy

Answer 2

You should have a look at a java profiler. For example VisualVM, which will analyze your CPU and RAM use in real time.

Answer 3

High CPU utilization is ok if there is actually some work in progress. i.e. if there are many live threads performing, the net CPU usage for java application will always be at its peak. It is usually instantaneous, i.e. should get normal again when there are no tasks.

I would suggest to:

1. Take multiple thread dumps (3-4) after a fix interval (1-2 seconds) (can use kill command on linux, jstack , jvisualvm, jconsole on all systems with jdk)

2. execute ps -mo pid,lwp,stime,time,%cpu,%mem -C java | less . This will list the lightweight processes under the java application's process id.
   

3. Get the process ids of the processes LWP with highest cpu/memory % (as targeted)

4. convert the lwp ids in to hexadecimal values, can use echo "obase=16; 255" | bc
   

5. Map these hex ids as nid='some_hex_vlaue' in the thread dump to find the details of thread corresponding to high cpu usage.
   e.g: "main" prio=10 tid=0x00007f54a4006800 nid=0x79ab runnable [0x00007f54a8340000]

Now we know the thread/s within the java process with highest resource(can be used for both memory/cpu%) usage.

I would also recommend to attach your jvm process to jvisualvm or jconsole and reproduce the problem, this way you can monitor your application’s state at all the time (from normal to issue reproduction) and take snapshots for reference. Both are good enough to perform any java threads or memory related profiling.
http://docs.oracle.com/javase/7/docs/technotes/guides/visualvm/
http://docs.oracle.com/javase/6/docs/technotes/guides/management/jconsole.html

Analyzing thread dumps can only point to the problem areas. At times its tricky, usually with high impact, but the cause and fix will be small. Actual cause would usually be either the way application is coded. i.e. How concurrency is managed. If a process is listening infinitely instead of waiting for notification, deadlocks due to synchronization issues etc or the system environment/external interfaces. i.e. file r/w on disk or remote locations, transfer using a ftp APIs or may be db operations etc.

Here is one useful post at dzone: http://architects.dzone.com/articles/how-analyze-java-thread-dumps

Hope it helps.