Debugging High CPU usage in Java Applications.
By Jose Luis Sanguino on Monday, December 9, 2019
For the past few years, I’ve been working supporting Integration Platforms in SOA environments (Service Oriented Architecture). During this time I’ve noticed that one of the critical points that put Administrators on alert is the High CPU consumption, beyond what was expected.
This condition could make running processes slow or even hang due to the lack of CPU resources. Obviously, impacting the performance of the Integration. Think about the repercussions this can have on banking or retail transactions.
Fortunately, there are different ways to prevent and solve this issue before it becomes more serious.
What we are going to see now, is a way to determine what is causing this High CPU usage in Java Applications.
Only as a brief introduction, a Java application contains several Threads that are basically a series of statements in execution. Each thread has its own state. For example, Runnable, Waiting, Blocked, Terminated, etc.
I’m assuming you have the basic knowledge of this topic.
When High CPU usage is observed, it’s usually related to a Java Thread(s) and we need to find out which of these threads is using this CPU.
In order to determine this, we can consider the following options:
I.) When the server has limited access and you don’t have the option to install any additional application/tool.
Linux:
Collect the following information when high CPU usage is observed.
1. Run the following command and capture the output:
ps -eLo pid,lwp,ruser,pcpu | grep <java_application_pid>
2. Immediately after the above command is excecuted, capture the thread dump of the Java application.
Steps below:
Use kill command to generate thread dump.
Steps:
a. Go to <java_application_path>/<application_name>
b. Run the following command from the command line, in order to start the application redirecting standard output to file.
<application_name> > Java_application.out 2>&1
c. Then, run the following command to generate a thread dump.
kill -3 <java_application_pid>
The thread dump will be written to the file Java_application.out
Note:
The kill command will not kill the application. The application will keep running and the thread-dump will be generated in the stderr/stdout of the application.
Here is an example of the outputs:
mulv1@vmul01$ ps -eLo pid,lwp,ruser,pcpu | grep 15231
15231 15896 muuser 0.0
15231 15897 muuser 0.0
15231 15898 muuser 0.0
15231 15899 muuser 2.7
15231 15900 muuser 0.0
15231 15901 muuser 2.8
15231 15902 muuser 28.6
15231 15903 muuser 2.7
15231 15904 muuser 2.5
15231 15905 muuser 28.7
15231 15906 muuser 2.7
15231 15907 muuser 26.8
15231 15908 muuser 0.0
15231 15909 muuser 2.6
15231 15910 muuser 0.0
15231 15911 muuser 0.0
15231 19859 muuser 0.0
15231 24042 muuser 0.0
We can see that only 3 threads (15902,15905,15907) are consuming around 84% of the CPU. This is something that must be checked.
The Thread dump must be reviewed in order to find out what these threads are doing.
(Only an extract of the Thread dump)
2019-10-16 17:18:53
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.221-b11 mixed mode):
“Attach Listener” #5471 daemon prio=9 os_prio=0 tid=0x00007f0e2000d800 nid=0x5dea waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
– None
“JobSelect.Reminder” #12 prio=7 os_prio=0 tid=0x00007f0de00af000 nid=0x4d93 in Object.wait() [0x00007f0e04107000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at com.mul.lev.util.Queue.run(Unknown Source)
– locked <0x00000000c0916748> (a java.lang.Object)
Locked ownable synchronizers:
– None
“I/O dispatcher 50” #137 prio=7 os_prio=0 tid=0x00007f0dc4575000 nid=0x3e1e runnable [0x00007f0e04548000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
– locked <0x00000000c7080a58> (a sun.nio.ch.Util$3)
– locked <0x00000000c7080a48> (a java.util.Collections$UnmodifiableSet)
– locked <0x00000000c7080910> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:255)
at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:104)
at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:588)
at java.lang.Thread.run(Thread.java:748)
Locked ownable synchronizers:
– None
“I/O dispatcher 49” #136 prio=7 os_prio=0 tid=0x00007f0dc4573000 nid=0x3e21 runnable [0x00007f0e04589000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
– locked <0x00000000c70d19d8> (a sun.nio.ch.Util$3)
– locked <0x00000000c70d19c8> (a java.util.Collections$UnmodifiableSet)
– locked <0x00000000c70d1890> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:255)
at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:104)
at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:588)
at java.lang.Thread.run(Thread.java:748)
Locked ownable synchronizers:
– None
“I/O dispatcher 48” #135 prio=7 os_prio=0 tid=0x00007f0dc4571000 nid=0x3e23 runnable [0x00007f0e045ca000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
– locked <0x00000000c70d1ee0> (a sun.nio.ch.Util$3)
– locked <0x00000000c70d1ed0> (a java.util.Collections$UnmodifiableSet)
– locked <0x00000000c70d1d98> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:255)
at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:104)
at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:588)
at java.lang.Thread.run(Thread.java:748)
Locked ownable synchronizers:
– None
If we notice, each Thread has its own identifier “nid”.
For example, the thread “I/O dispatcher 50” #137 has a nid=0x3e1e, in this case the “nid” is in Hexadecimal notation.
To find out the Threads with High CPU usage, we need to correlate the information between the output of “ps” command and thread dump.
We already know that there are 3 threads consuming High CPU: 15902, 15905, 15907. They are in decimal notation, so if I convert 15902 from decimal to hexadecimal I get 0x3e1e, the thread with this id is the following:
“I/O dispatcher 50” #137 prio=7 os_prio=0 tid=0x00007f0dc4575000 nid=0x3e1e runnable [0x00007f0e04548000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
– locked <0x00000000c7080a58> (a sun.nio.ch.Util$3)
– locked <0x00000000c7080a48> (a java.util.Collections$UnmodifiableSet)
– locked <0x00000000c7080910> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:255)
at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:104)
at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:588)
at java.lang.Thread.run(Thread.java:748)
This means that some processes running on Apache using nio classes are causing this High CPU.
If you are an administrator you could check this information with your development team.
II.) When the server has limited access but at least Java JDK is installed.
Collect the following information when high CPU usage is observed.
1. Run the following command and capture the output.
ps -eLo pid,lwp,ruser,pcpu | grep <java_application_pid>
2. Immediately after the above command is executed, capture the thread dump of bwengine. Steps below:
If JDK is installed on the machine where BW application is running, use jstack utility to generate thread dump.
jstack -l <java_application_pid> > threaddump.txt
The thread dump will be written to the file threaddump.txt
Then proceed to correlate the information between the ps command and the jstack output as we did before.
III.) When we have the option of installing additional tools on our server.
From my point of view and regardless of the OS, the easiest way to get the information about the threads consuming High CPU in Java applications is to use “jvmtop” tool.
This is a small application that can be downloaded from this url: https://github.com/patric-r/jvmtop
Basically, we need to execute this tool as follows:
jvmtop <java_application_pid>
Note:
We must have installed JDK on the server to run the utility, JRE is not enough. We also have to set the JAVA_HOME and add it to the path.
The output will show the top 10 threads of the Java application that are using the highest amount of CPU.
The output window will look like the one below:
IV.) For Windows environments.
1. Use Process Explorer to capture CPU usage data. It can be downloaded from https://docs.microsoft.com/en-us/sysinternals/downloads/process-explorer.
Steps:
– Launch Process Explorer.
– Locate the Java process. If there are multiple Java processes, use Command Line column value to identify the process in question.
– Right-click and select Properties.
– In the Properties window, select the Threads tab for CPU usage data.
2. Immediately after collecting CPU usage data, take a thread dump of Java process.
3. Correlate the information between the threads with High CPU in Process Explorer and the threads from the Thread dumps as we suggested above.
References:
RedHat. (2019, October 28). How do I generate a Java thread dump on Linux/Unix? Retrieved December 4, 2019, from https://access.redhat.com/solutions/18178
Author: Jose Luis Sanguino
