jstack命令解析

最新推荐文章于 2024-06-26 22:30:32 发布

小懒虫不想写博客

最新推荐文章于 2024-06-26 22:30:32 发布

阅读量627

点赞数

原文链接：https://blog.csdn.net/baiye_xing/article/details/90483169

版权

高cpu，高内存的Java进程排查方法

jstack查看输出

/opt/java8/bin/jstack -l 28367

2019-06-25 15:04:46
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.77-b03 mixed mode):

"Attach Listener" #453 daemon prio=9 os_prio=0 tid=0x00007f9f94001000 nid=0xf30 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"grpc-default-executor-263" #452 daemon prio=5 os_prio=0 tid=0x00007f9f4c01f800 nid=0x9aa waiting on condition [0x00007f9f398bd000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000007400243f0> 

   Locked ownable synchronizers:
        - None

jstack统计线程数

/opt/java8/bin/jstack -l 28367 | grep 'java.lang.Thread.State' | wc -l

查看cpu高

代码中某个位置读取数据量较大，导致系统内存耗尽，从而导致Full GC次数过多，系统缓慢；
代码中有比较耗CPU的操作，导致CPU过高，系统运行缓慢；

另外有几种情况也会导致某个功能运行缓慢，但是不至于导致系统不可用：

代码某个位置有阻塞性的操作，导致该功能调用整体比较耗时，但出现是比较随机的；
某个线程由于某种原因而进入WAITING状态，此时该功能整体不可用，但是无法复现；
由于锁使用不当，导致多个线程进入死锁状态，从而导致系统整体比较缓慢。

对于这三种情况，通过查看CPU和系统内存情况是无法查看出具体问题的，因为它们相对来说都是具有一定阻塞性操作，CPU和系统内存使用情况都不高，但是功能却很慢

top命令查看系统CPU的占用情况：top

top命令查看呢该进程的各个线程运行情况：top -Hp 9

替换进程id号为十六进制：# printf "%x\n" 10

定位cpu占用线程： jstack 进程id | grep 线程id十六进制 -A 30

检查到死锁日志：

"mythread2" #12 prio=5 os_prio=0 tid=0x0000000058ef7800 nid=0x1ab4 waiting on condition [0x0000000059f8f000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000d602d610> (a java.util.concurrent.lock
s.ReentrantLock$NonfairSync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInt
errupt(AbstractQueuedSynchronizer.java:836)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(A
bstractQueuedSynchronizer.java:870)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(Abstrac
tQueuedSynchronizer.java:1199)
        at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLo
ck.java:209)
        at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)

        at DeathLock$2.run(DeathLock.java:34)

   Locked ownable synchronizers:
        - <0x00000000d602d640> (a java.util.concurrent.locks.ReentrantLock$Nonfa
irSync)

"mythread1" #11 prio=5 os_prio=0 tid=0x0000000058ef7000 nid=0x3e68 waiting on condition [0x000000005947f000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000d602d640> (a java.util.concurrent.lock
s.ReentrantLock$NonfairSync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInt
errupt(AbstractQueuedSynchronizer.java:836)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(A
bstractQueuedSynchronizer.java:870)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(Abstrac
tQueuedSynchronizer.java:1199)
        at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLo
ck.java:209)
        at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)

        at DeathLock$1.run(DeathLock.java:22)

   Locked ownable synchronizers:
        - <0x00000000d602d610> (a java.util.concurrent.locks.ReentrantLock$Nonfa
irSync)


Found one Java-level deadlock:
=============================
"mythread2":
  waiting for ownable synchronizer 0x00000000d602d610, (a java.util.concurrent.l
ocks.ReentrantLock$NonfairSync),
  which is held by "mythread1"
"mythread1":
  waiting for ownable synchronizer 0x00000000d602d640, (a java.util.concurrent.l
ocks.ReentrantLock$NonfairSync),
  which is held by "mythread2"

Java stack information for the threads listed above:
===================================================
"mythread2":
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000d602d610> (a java.util.concurrent.lock
s.ReentrantLock$NonfairSync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInt
errupt(AbstractQueuedSynchronizer.java:836)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(A
bstractQueuedSynchronizer.java:870)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(Abstrac
tQueuedSynchronizer.java:1199)
        at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLo
ck.java:209)
        at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)

        at DeathLock$2.run(DeathLock.java:34)
"mythread1":
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000d602d640> (a java.util.concurrent.lock
s.ReentrantLock$NonfairSync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInt
errupt(AbstractQueuedSynchronizer.java:836)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(A
bstractQueuedSynchronizer.java:870)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(Abstrac
tQueuedSynchronizer.java:1199)
        at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLo
ck.java:209)
        at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)

        at DeathLock$1.run(DeathLock.java:22)

Found 1 deadlock.

如果通过jstack命令看到以下日志

"main" #1 prio=5 os_prio=0 tid=0x00007f8718009800 nid=0xb runnable [0x00007f871fe41000]
   java.lang.Thread.State: RUNNABLE
    at com.aibaobei.chapter2.eg2.UserDemo.main(UserDemo.java:9)

"VM Thread" os_prio=0 tid=0x00007f871806e000 nid=0xa runnable

这里的VM Thread一行的最后显示nid=0xa，这里nid的意思就是操作系统线程id的意思。而VM Thread指的就是垃圾回收的线程。这里我们基本上可以确定，当前系统缓慢的原因主要是垃圾回收过于频繁，导致GC停顿时间较长。我们通过如下命令可以查看GC的情况：

root@8d36124607a0:/# jstat -gcutil 9 1000 10
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
  0.00   0.00   0.00  75.07  59.09  59.60   3259    0.919  6517    7.715    8.635
  0.00   0.00   0.00   0.08  59.09  59.60   3306    0.930  6611    7.822    8.752
  0.00   0.00   0.00   0.08  59.09  59.60   3351    0.943  6701    7.924    8.867
  0.00   0.00   0.00   0.08  59.09  59.60   3397    0.955  6793    8.029    8.984

root@8d36124607a0:/# jstat -gcutil 9 1000 10
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
  0.00   0.00   0.00  75.07  59.09  59.60   3259    0.919  6517    7.715    8.635
  0.00   0.00   0.00   0.08  59.09  59.60   3306    0.930  6611    7.822    8.752
  0.00   0.00   0.00   0.08  59.09  59.60   3351    0.943  6701    7.924    8.867
  0.00   0.00   0.00   0.08  59.09  59.60   3397    0.955  6793    8.029    8.984

可以看到，这里FGC指的是Full GC数量，这里高达6793，而且还在不断增长。从而进一步证实了是由于内存溢出导致的系统缓慢。

Java高CPU占用排查步骤

top：找到占用CPU高的进程PID
jstack PID >> java_stack.log：导出CPU占用高进程的线程栈
top -Hp PID：找出PID的进程占用CPU过高的线程tid。（或使用命令 ps -mp PID -o THREAD,tid,time | sort -rn | less）
printf “%x\n” tid：将需要的线程ID转换为16进制格式。
less java_stack.log：查找转换成为16进制的线程TID，找到对应的线程栈，分析并处理问题。

Java高内存占用排查步骤

top：找到占用内存(RES列)高的Java进程PID。
jmap -heap PID：查看heap内存使用情况。
jps -lv ：查看JVM参数配置。
jstat -gc PID 1000：收集每秒堆的各个区域具体占用大小的gc信息。
jmap -dump:live,format=b,file=heap_dump.hprof PID ：导出堆文件。
使用MAT打开堆文件，分析问题。

Java堆外内存泄漏排查步骤

top：找到占用内存(RES列)较高的Java进程PID。
jstat -gcutil PID 1000 查看每秒各个区域占堆百分比，若gc正常，则分析堆外内存使用情况。
jcmd PID VM.native_memory detail，该命令需要添加JVM参数 -XX:NativeMemoryTracking=detail，并重启Java进程才能生效，该命令会显示内存使用情况，查看输出结果，总的committed的内存是否小于物理内存（RES），因为jcmd命令显示的内存包含堆内内存、Code区域、通过unsafe.allocateMemory和DirectByteBuffer申请的内存，但是不包含其他Native Code（C代码）申请的堆外内存。
pmap -x PID | sort -rn -k 3：查看内存分布，是否有地址空间不在jcmd命令所给出的地址空间中。
用工具定位堆外内存，如gperftools、gdb、strace等。

主要是怕这位大佬的文章突然看不到了，搬运备份学习。搬运工自这位大佬：https://blog.csdn.net/baiye_xing/article/details/90483169