{"id":2430,"date":"2012-08-08T06:32:37","date_gmt":"2012-08-08T11:32:37","guid":{"rendered":"http:\/\/appcrawler.com\/wordpress\/?p=2430"},"modified":"2012-08-15T08:09:12","modified_gmt":"2012-08-15T13:09:12","slug":"finding-java-thread-consuming-cpu","status":"publish","type":"post","link":"http:\/\/appcrawler.com\/wordpress\/2012\/08\/08\/finding-java-thread-consuming-cpu\/","title":{"rendered":"Finding java thread consuming CPU"},"content":{"rendered":"

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.<\/p>\n

1.\tAs the user running the Java Virtual Machine (\u201cJVM\u201d), get the currently running java processes on the server\u2026<\/p>\n

\r\n-bash-4.1$ jps\r\n19308 Jps\r\n25252 Main\r\n-bash-4.1$\r\n<\/pre>\n
2.\t\u2026and for the the \u201cMain\u201d thread, get the top CPU consumer.  There can be more than one \u201cMain\u201d 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 \u201cShift H\u201d 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.<\/p>\n
Run what is below a few times and it will probably bubble to the top.  If not, use the top method noted above.<\/p>\n
\r\n-bash-4.1$ ps -eLf | grep 25252 | sort -k +9 | tail -1 | awk '{i=1;while (i++ <= 11) {printf(\"%s \",$i)};printf(\"\\n\")}'\r\n25252 25205 25301 29 219 Aug07 ? 04:08:34 java -Dprogram.name=run.sh -server\r\n<\/pre>\n
3.\t\u2026then convert the thread number (third \"column\" in the output above) to hexadecimal\u2026<\/p>\n
\r\n-bash-4.1$-bash-4.1$ printf \"%x\\n\" 25301\r\n62d5\r\n<\/pre>\n
4.\t\u2026then 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\u2026<\/p>\n
\r\n-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}}'\r\n\"Thread-9\" daemon prio=10 tid=0x00007f12e747b000 nid=0x62d5 runnable [0x00007f131340b000]\r\n   java.lang.Thread.State: RUNNABLE\r\n        at org.apache.log4j.Category.getEffectiveLevel(Category.java:439)\r\n        at org.apache.log4j.Category.isDebugEnabled(Category.java:733)\r\n        at com.arjuna.common.internal.util.logging.jakarta.Log4JLogger.isDebugEnabled(Log4JLogger.java:317)\r\n        at com.arjuna.common.internal.util.logging.jakarta.JakartaRelevelingLogger.isDebugEnabled(JakartaRelevelingLogger.java:73)\r\n        at com.arjuna.common.internal.util.logging.LogImpl.isDebugEnabled(LogImpl.java:142)\r\n        at com.arjuna.ats.arjuna.coordinator.TransactionReaper.check(TransactionReaper.java:180)\r\n        - locked <0x00000006fd3b6ac0> (a com.arjuna.ats.arjuna.coordinator.TransactionReaper)\r\n        at com.arjuna.ats.internal.arjuna.coordinator.ReaperThread.run(ReaperThread.java:122)\r\n\r\n\r\n-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}}'\r\n\"Thread-9\" daemon prio=10 tid=0x00007f12e747b000 nid=0x62d5 runnable [0x00007f131340b000]\r\n   java.lang.Thread.State: RUNNABLE\r\n        at org.apache.log4j.Category.getEffectiveLevel(Category.java:439)\r\n        at org.apache.log4j.Category.isDebugEnabled(Category.java:733)\r\n        at com.arjuna.common.internal.util.logging.jakarta.Log4JLogger.isDebugEnabled(Log4JLogger.java:317)\r\n        at com.arjuna.common.internal.util.logging.jakarta.JakartaRelevelingLogger.isDebugEnabled(JakartaRelevelingLogger.java:73)\r\n        at com.arjuna.common.internal.util.logging.LogImpl.isDebugEnabled(LogImpl.java:142)        at com.arjuna.ats.arjuna.coordinator.TransactionReaper.check(TransactionReaper.java:180)\r\n        - locked <0x00000006fd3b6ac0> (a com.arjuna.ats.arjuna.coordinator.TransactionReaper)\r\n        at com.arjuna.ats.internal.arjuna.coordinator.ReaperThread.run(ReaperThread.java:122)\r\n-bash-4.1$\r\n<\/pre>\n
Another quick way to get the methods being called is to use what is below:<\/p>\n
\r\njps\r\nwatch -n1 'jstack [relevant PID obtained above] | grep -A 1 RUNNABLE | egrep -v \"RUNNABLE|^-|socketRead0|socketAccept\"'\r\n<\/pre>\n","protected":false},"excerpt":{"rendered":"
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…<\/p>\n
Read more →<\/a><\/p>\n","protected":false},"author":2,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"_mi_skip_tracking":false,"footnotes":""},"categories":[24,25],"tags":[],"_links":{"self":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts\/2430"}],"collection":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/users\/2"}],"replies":[{"embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/comments?post=2430"}],"version-history":[{"count":9,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts\/2430\/revisions"}],"predecessor-version":[{"id":2442,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts\/2430\/revisions\/2442"}],"wp:attachment":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/media?parent=2430"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/categories?post=2430"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/tags?post=2430"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}