Wednesday, May 29, 2013

How to find the culprit when CPU starts to spin?




When your JAVA process started to spin your CPU, you need to immediately issue following two commands and get the invaluable information required to tackle the issue.

1. jstack <pid> > thread-dump.txt
2. ps -C java -L -o pcpu,cpu,nice,state,cputime,pid,tid > thread-usage.txt

After getting those two files, what you can do is,

1. find the thread ID (which belongs to the corresponding PID ) which takes the highest CPU usage by examine thread-usage.txt file.

%CPU CPU  NI S     TIME   PID   TID
..........
  0.0   -   0 S 00:00:00  1519  1602
  0.0   -   0 S 00:00:00  1519  1603
24.8   -   0 R 00:06:19  1519  1604
  2.4   -   0 S 00:00:37  1519  1605
  0.0   -   0 S 00:00:00  1519  1606
..........


2. convert the decimal value (in this case 1604) to hexadecimal - (online converter - http://easycalculation.com/decimal-converter.php)

Hex - 644



3. search for the hexadecimal obtained (in this case 644) in the thread-dump.txt (thread-dump.txt should have that value as a thread id of one thread) and that is the thread which spins.
4. that thread usually has a stack trace, and that's the lead to find the culprit.

In this case the stack trace of the thread that spins is:

"HTTPS-Sender I/O dispatcher-1" prio=10 tid=0x00007fb54c010000 nid=0x644 runnable [0x00007fb534e20000]
   java.lang.Thread.State: RUNNABLE
        at org.apache.http.impl.nio.reactor.IOSessionImpl.getEventMask(IOSessionImpl.java:139)
        - locked <0x00000006cd91fef8> (a org.apache.http.impl.nio.reactor.IOSessionImpl)
        at org.apache.http.nio.reactor.ssl.SSLIOSession.updateEventMask(SSLIOSession.java:300)
        at org.apache.http.nio.reactor.ssl.SSLIOSession.inboundTransport(SSLIOSession.java:402)
        - locked <0x00000006cd471df8> (a org.apache.http.nio.reactor.ssl.SSLIOSession)
        at org.apache.http.impl.nio.reactor.AbstractIODispatch.inputReady(AbstractIODispatch.java:121)
        at org.apache.http.impl.nio.reactor.BaseIOReactor.readable(BaseIOReactor.java:160)
        at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(AbstractIOReactor.java:342)
        at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(AbstractIOReactor.java:320)
        at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:280)
        at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:106)
        at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:604)
        at java.lang.Thread.run(Thread.java:722)
Hope this helps!

5 comments:

Viraj Rajaguru said...

Hi Nirmal,

Thank you for sharing knowledge !!!

I'm using JDK 1.7. when I'm going to run 'jstack' command in the console, it ask me to specify a 'PID'. Just issuing 'jstack' command gives nothing to me.
Am I doing something wrong here ?

Thanks,
Viraj.

Nirmal Fernando said...

Hi Viraj,

Thanks for the feedback. I actually added the jstack > thread-dump.txt but forgot to replace < characters with < etc. Fixed it now.
Thanks.

Nirmal Fernando said...

For OS X users; You can get the thread usage using following command-

ps M

eg: $ps M 40482

Nirmal Fernando said...
This comment has been removed by the author.
Nirmal Fernando said...

ps M <PID>