Jstack 解读

T-note

2019-04-11

Java 中线程的状态

NEW 初始状态。
- 线程刚刚被创建，并且start()方法还未被调用
RUNNABLE 运行状态。
- 表示线程正在java虚拟机中执行，但是可能正在等待操作系统的其他资源，比如CPU
BLOCKED 阻塞状态。
- 表示线程正在等待监视器锁。表示线程正在等待获取监视器锁，以便进入同步方法或者同步代码快，也有可能是从wait（）方法被唤醒而等待再次进入同步方法或者同步代码块
WAITING 等待状态。
- 表示当前线程需要等待其他线程执行一些特殊操作，比如当前线程调用了a.wait()方法，它正在等待其他线程调用a.notify或a.notifyAll方法;如果当前线程调用了threada.join(),那么它在等待thread a执行完成
- 触发条件
  - Object.wait() 不设置超时时间
  - Thread.join() 不设置超时时间
  - LockSupport.park() 不设置超时时间
TIMED_WAITING 超时等待。
- 与WAITING的不同在于，该状态有超时时间
- 触发条件
  - Object.wait(time)
  - Thread.join(time)
  - Thread.sleep(time)
  - LockSupport.parkNanos(time)
  - LockSupport.parkUntil(time)
TERMINATED 终止状态
- 表示当前线程已经执行完毕

统计 jstack 中各个状态的线程数量 slick-dead: 线程堆栈文件

1	awk -F: '/java.lang.Thread.State/ {c[$2]++}; END {for(t in c) print t, c[t]}' slick-dead \| sort -rn -k 2

排查 CPU 高

找到 java 进程

jps

info

3186 Kafka
2789 QuorumPeerMain
6056 ApiBootstrap
27640 Jps

找到占用CPU 高的 java 线程ID

top -H -p JAVA_PID

info

top - 11:58:21 up 1 day,  2:42,  2 users,  load average: 5.53, 5.71, 5.67
Threads:  40 total,   9 running,  31 sleeping,   0 stopped,   0 zombie
%Cpu(s): 38.3 us, 25.0 sy,  0.0 ni, 35.0 id,  0.0 wa,  0.0 hi,  0.0 si,  1.7 st
KiB Mem : 16235220 total, 14041692 free,  1565180 used,   628348 buff/cache
KiB Swap:        0 total,        0 free,        0 used. 14347812 avail Mem

PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
6103 apps      20   0 7850124 378852  21004 S 33.3  2.3 328:41.42 java
6091 apps      20   0 7850124 378852  21004 R 26.7  2.3 363:05.92 java
6092 apps      20   0 7850124 378852  21004 R 26.7  2.3 356:59.78 java
6096 apps      20   0 7850124 378852  21004 R 26.7  2.3 329:02.12 java
6104 apps      20   0 7850124 378852  21004 S 26.7  2.3 334:30.68 java
6105 apps      20   0 7850124 378852  21004 R 26.7  2.3 333:58.77 java
6094 apps      20   0 7850124 378852  21004 R 20.0  2.3 324:20.23 java
6095 apps      20   0 7850124 378852  21004 R 20.0  2.3 332:13.38 java
6100 apps      20   0 7850124 378852  21004 S 20.0  2.3 368:29.35 java
6101 apps      20   0 7850124 378852  21004 R 20.0  2.3 337:29.08 java
6102 apps      20   0 7850124 378852  21004 R 20.0  2.3 327:07.27 java
6093 apps      20   0 7850124 378852  21004 R 13.3  2.3 325:53.33 java

保存 jvm 线程堆栈

1	jstack -l JAVA_PID > /tmp/stack.JAVA_PID

根据 TOP 展示的高CPU线程ID，找到 jstack 中对应的 java 代码块

 cat /tmp/api.6056 | grep `printf %x JAVA_PID` -A 20

 info

 "log2kafka-worker-3" #27 prio=5 os_prio=0 tid=0x00007fce6e2c3000 nid=0x17d7 runnable [0x00007fce526e5000]
  java.lang.Thread.State: TIMED_WAITING (parking)
 at sun.misc.Unsafe.park(Native Method)
 at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
 at com.lmax.disruptor.SleepingWaitStrategy.applyWaitMethod(SleepingWaitStrategy.java:92)
 at com.lmax.disruptor.SleepingWaitStrategy.waitFor(SleepingWaitStrategy.java:65)
 at com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarrier.java:56)
 at com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:159)
 at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:125)
 at java.lang.Thread.run(Thread.java:745)

  Locked ownable synchronizers:
 - None

"log2kafka-worker-2" #26 prio=5 os_prio=0 tid=0x00007fce6e2c1000 nid=0x17d6 runnable [0x00007fce527e6000]
  java.lang.Thread.State: TIMED_WAITING (parking)
 at sun.misc.Unsafe.park(Native Method)
 at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
 at com.lmax.disruptor.SleepingWaitStrategy.applyWaitMethod(SleepingWaitStrategy.java:92)
 at com.lmax.disruptor.SleepingWaitStrategy.waitFor(SleepingWaitStrategy.java:65)
 at com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarrier.java:56)