Thread dump analysis

It can happen that a thread name does not include a unique counter that is increase whenever new thread is created in the pool. In that case, use thread nid, e.g.

"Thread-1" #19 prio=5 os_prio=0 tid=0x00000000051db800 nid=0xdd5 runnable [0x00002ae6063ac000]

that can be scripted by e.g.:

grep -e '".*"' jstack.log | sed 's/"\ .*nid=/",/' | egrep -oh '.*,[0-9A-Za-z]+' | sort

to get:

"Thread-1",0xdd5

other examples after scripting:

"JMX Monitor ThreadGroup<main> Executor Pool [Thread-71]",0x52ed
"JMX Monitor ThreadGroup<main> Executor Pool [Thread-72]",0x7a8f
"RMI TCP Connection(idle)",0x580a
"RMI TCP Connection(idle)",0x5d7d

example:

One JVM process id : 3103 (PID – Process ID)
One JVM parent process id (PPID – Parent Process ID)
Many threads ids: 3103, 3104, …, 3602, 3605 , 3643  (LWP – light weight process id) that are listed in the thread dump as shown below:

 

UID PID PPID LWP C NLWP STIME TTY TIME CMD
$ ps -eLf | grep tktdev | grep 3103 | grep java
tktdev 3103 2746 3103 0 37 03:25 pts/0 00:00:00 /opt/jdk1.8.0_45/bin/java -cp . com.bawi.cyclicbarrier.MyCyclicBarrier
tktdev 3103 2746 3104 0 37 03:25 pts/0 00:00:00 /opt/jdk1.8.0_45/bin/java -cp . com.bawi.cyclicbarrier.MyCyclicBarrier
...
tktdev 3103 2746 3602 99 37 03:25 pts/0 00:09:17 /opt/jdk1.8.0_45/bin/java -cp . com.bawi.cyclicbarrier.MyCyclicBarrier
tktdev 3103 2746 3605 99 37 03:25 pts/0 00:09:17 /opt/jdk1.8.0_45/bin/java -cp . com.bawi.cyclicbarrier.MyCyclicBarrier
tktdev 3103 2746 3643 99 37 03:25 pts/0 00:09:17 /opt/jdk1.8.0_45/bin/java -cp . com.bawi.cyclicbarrier.MyCyclicBarrier
tktdev 3103 2746 11475 0 37 03:29 pts/0 00:00:00 /opt/jdk1.8.0_45/bin/java -cp . com.bawi.cyclicbarrier.MyCyclicBarrier

Showing CPU usage per thread (with Hyper-threading option) (result filtered)
top -H 

 PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
 3602 tktdev 25 0 13.8g 28m 11m R 99.9 0.1 10:38.74 java
 3605 tktdev 25 0 13.8g 28m 11m R 99.9 0.1 10:38.74 java
 3643 tktdev 25 0 13.8g 28m 11m R 99.9 0.1 10:38.74 java

Getting java PID:

$ /opt/jdk1.8.0_45/bin/jcmd
3103 com.bawi.cyclicbarrier.MyCyclicBarrier

Creating thread dump via jstack:

$ /opt/jdk1.8.0_45/bin/jstack -l 3103 > jstack.log

Filtered content of thread dump:

"Thread-2" #20 prio=5 os_prio=0 tid=0x00002ac1f4013800 nid=0xe3b runnable [0x00002ac1eec0f000] (note: nid=0xe3b (in hex)== 3643 (in dec))
 java.lang.Thread.State: RUNNABLE
 at com.bawi.cyclicbarrier.MyCyclicBarrier.lambda$createAndStartNewThread$0(MyCyclicBarrier.java:23)
 at com.bawi.cyclicbarrier.MyCyclicBarrier$$Lambda$1/791452441.run(Unknown Source)
 at java.lang.Thread.run(Thread.java:745)
Locked ownable synchronizers:
 - None
"Thread-1" #19 prio=5 os_prio=0 tid=0x00002ac1f4011800 nid=0xe15 runnable [0x00002ac1eeb0e000] (note: nid=0xe15 (in hex)== 3605 (in dec))
 java.lang.Thread.State: RUNNABLE
 at com.bawi.cyclicbarrier.MyCyclicBarrier.lambda$createAndStartNewThread$0(MyCyclicBarrier.java:23)
 at com.bawi.cyclicbarrier.MyCyclicBarrier$$Lambda$1/791452441.run(Unknown Source)
 at java.lang.Thread.run(Thread.java:745)
Locked ownable synchronizers:
 - None
"Thread-0" #18 prio=5 os_prio=0 tid=0x00002ac1f4010000 nid=0xe12 runnable [0x00002ac1eea0d000] (note: nid=0xe12 (in hex)== 3602 (in dec))
 java.lang.Thread.State: RUNNABLE
 at com.bawi.cyclicbarrier.MyCyclicBarrier.lambda$createAndStartNewThread$0(MyCyclicBarrier.java:23)
 at com.bawi.cyclicbarrier.MyCyclicBarrier$$Lambda$1/791452441.run(Unknown Source)
 at java.lang.Thread.run(Thread.java:745)
Locked ownable synchronizers:
 - None

					
Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s