Periodically, we will have an application server go to 100% CPU utilization on a single java process. Below is the methodology I use to troubleshoot a high CPU thread consumer in java.
1. As the user running the Java Virtual Machine (“JVM”), get the currently running java processes on the server…
-bash-4.1$ jps
19308 Jps
25252 Main
-bash-4.1$
2. …and for the the “Main” thread, get the top CPU consumer. There can be more than one “Main” thread, in which case you will have to issue a “ps -ef | grep java”, and figure out which one is the high CPU user by looking at the seventh “column” in the output. You can also type “Shift H” in top. You may see several threads, each of which uses a second or two of CPU every few seconds. This indicates an application throughput issue, and not a single thread problem.
Run what is below a few times and it will probably bubble to the top. If not, use the top method noted above.
-bash-4.1$ ps -eLf | grep 25252 | sort -k +9 | tail -1 | awk '{i=1;while (i++ <= 11) {printf("%s ",$i)};printf("\n")}'
25252 25205 25301 29 219 Aug07 ? 04:08:34 java -Dprogram.name=run.sh -server
3. …then convert the thread number (third "column" in the output above) to hexadecimal…
-bash-4.1$-bash-4.1$ printf "%x\n" 25301
62d5
4. …then finally get a stack trace for that thread a few different times. It will probably be on a class method named something similar in each check…
-bash-4.1$ jstack 25252 | awk '{if ($0 ~ "nid=0x62d5" && p==0) {p=1;print} else if (p==1 && length($0) > 1) {print} else if (p==1) {p=0}}'
"Thread-9" daemon prio=10 tid=0x00007f12e747b000 nid=0x62d5 runnable [0x00007f131340b000]
java.lang.Thread.State: RUNNABLE
at org.apache.log4j.Category.getEffectiveLevel(Category.java:439)
at org.apache.log4j.Category.isDebugEnabled(Category.java:733)
at com.arjuna.common.internal.util.logging.jakarta.Log4JLogger.isDebugEnabled(Log4JLogger.java:317)
at com.arjuna.common.internal.util.logging.jakarta.JakartaRelevelingLogger.isDebugEnabled(JakartaRelevelingLogger.java:73)
at com.arjuna.common.internal.util.logging.LogImpl.isDebugEnabled(LogImpl.java:142)
at com.arjuna.ats.arjuna.coordinator.TransactionReaper.check(TransactionReaper.java:180)
- locked <0x00000006fd3b6ac0> (a com.arjuna.ats.arjuna.coordinator.TransactionReaper)
at com.arjuna.ats.internal.arjuna.coordinator.ReaperThread.run(ReaperThread.java:122)
-bash-4.1$ jstack 25252 | awk '{if ($0 ~ "nid=0x62d5" && p==0) {p=1;print} else if (p==1 && length($0) > 1) {print} else if (p==1) {p=0}}'
"Thread-9" daemon prio=10 tid=0x00007f12e747b000 nid=0x62d5 runnable [0x00007f131340b000]
java.lang.Thread.State: RUNNABLE
at org.apache.log4j.Category.getEffectiveLevel(Category.java:439)
at org.apache.log4j.Category.isDebugEnabled(Category.java:733)
at com.arjuna.common.internal.util.logging.jakarta.Log4JLogger.isDebugEnabled(Log4JLogger.java:317)
at com.arjuna.common.internal.util.logging.jakarta.JakartaRelevelingLogger.isDebugEnabled(JakartaRelevelingLogger.java:73)
at com.arjuna.common.internal.util.logging.LogImpl.isDebugEnabled(LogImpl.java:142) at com.arjuna.ats.arjuna.coordinator.TransactionReaper.check(TransactionReaper.java:180)
- locked <0x00000006fd3b6ac0> (a com.arjuna.ats.arjuna.coordinator.TransactionReaper)
at com.arjuna.ats.internal.arjuna.coordinator.ReaperThread.run(ReaperThread.java:122)
-bash-4.1$
Another quick way to get the methods being called is to use what is below:
jps
watch -n1 'jstack [relevant PID obtained above] | grep -A 1 RUNNABLE | egrep -v "RUNNABLE|^-|socketRead0|socketAccept"'