JVM之问题排除和优化

starlin 1,085 2020-08-24

今天总结下如何利用java自带的工具来排查生成环境的问题，先介绍下自带的工具，它们分别是：jps、jstat、jinfo、jmap、jhat、jstack，，它们都位于 JDK 的 bin 目录下，可以使用命令行工具直接运行，其目录如下图所示：
java文件bin目录-w287
接下来看看，这些工具的具体使用

1. jps（虚拟机进程查看工具）

jps（JVM Process Status tool，虚拟机进程状况工具）它的功能和 Linux 中的 ps 命令比较类似，用于列出正在运行的 JVM 的 LVMID（Local Virtual Machine IDentifier，本地虚拟机唯一 ID），以及 JVM 的执行主类、JVM 启动参数等信息。语法如下：

jps [options] [hostid]

常用的 options 选项：

  • l：用于输出运行主类的全名，如果是 jar 包，则输出 jar 包的路径；
  • q：用于输出 LVMID（Local Virtual Machine Identifier，虚拟机唯一 ID）；
  • m：用于输出虚拟机启动时传递给主类 main() 方法的参数；
  • v：用于输出启动时的 JVM 参数。

2. jstat（虚拟机统计信息监视工具）

jstat（JVM Statistics Monitoring Tool，虚拟机统计信息监视工具）用于监控虚拟机的运行状态信息。
例如，我们用它来查询某个 Java 进程的垃圾收集情况，示例如下：

➜  ~ jstat -gc 89546
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT
43520.0 43520.0  0.0    0.0   262144.0 83896.4   699392.0     0.0     4480.0 791.7  384.0   76.6       0    0.000   0      0.000    0.000

参数说明如下：

参数说明
S0C年轻代中第一个存活区的大小
S1C年轻代中第二个存活区的大小
S0U年轻代中第一个存活区已使用的空间（字节
S1U年轻代中第二个存活区已使用的空间（字节）
ECEdem 区大小
EU年轻代中 Edem 区已使用的空间（字节
OC老年代大小
OU老年代已使用的空间（字节）
YGC从应用程序启动到采样时 young gc 的次数
YGCT从应用程序启动到采样时 young gc 的所用的时间（s）
FGC从应用程序启动到采样时 full gc 的次数
FGCT从应用程序启动到采样时 full gc 的所用的时间
GCT从应用程序启动到采样时整个 gc 所用的时间

注意：年轻代的 Edem 区满了会触发 young gc，老年代满了会触发 old gc。full gc 指的是清除整个堆，包括 young 区 和 old 区。

jstat 常用的查询参数有：

  • class，查询类加载器信息；
  • compiler，JIT 相关信息；
  • gc，GC 堆状态；
  • gcnew，新生代统计信息；
  • gcutil，GC 堆统计汇总信息。

3. jinfo（查询虚拟机参数配置工具）

jinfo（Configuration Info for Java）用于查看和调整虚拟机各项参数。语法如下：

jinfo <option> <pid>

4. jmap（堆快照生成工具）

jmap（Memory Map for Java）用于查询堆的快照信息。
命令如下：

jmap -heap 89948

我们也可以直接生成堆快照文件，示例如下：

➜  ~ jmap -dump:format=b,file=/Users/starlin/2020.dump 89948
Dumping heap to /Users/starlin/2020.dump ...
Heap dump file created

5. jhat（堆快照分析功能）

jhat（JVM Heap Analysis Tool，堆快照分析工具）和 jmap 搭配使用，用于启动一个 web 站点来分析 jmap 生成的快照文件。
执行示例如下：

➜  ~ jhat /Users/starlin/2020.dump
Reading from /Users/starlin/2020.dump...
Dump file created Mon Aug 24 22:59:36 CST 2020
Snapshot read, resolving...
Resolving 333407 objects...
Chasing references, expect 66 dots..................................................................
Eliminating duplicate references..................................................................
Snapshot resolved.
Started HTTP server on port 7000
Server is ready.

上述信息表示 jhat 启动了一个 http 的服务器端口为 7000 的站点来展示信息，
此时我们在浏览器中输入：http://localhost:7000/，会看到如下图所示的信息：
jhat截图

6. jstack（查询虚拟机当前的线程快照信息）

jstack（Stack Trace for Java）用于查看当前虚拟机的线程快照，用它可以排查线程的执行状况，例如排查死锁、死循环等问题。
利用如下命令：

jstack -l 50016

显示如下：

Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.231-b11 mixed mode):

"RMI TCP Connection(2)-127.0.0.1" #30 daemon prio=9 os_prio=31 tid=0x00007fe0ce07d000 nid=0x9403 runnable [0x0000700004c2f000]
   java.lang.Thread.State: RUNNABLE
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
	at java.net.SocketInputStream.read(SocketInputStream.java:171)
	at java.net.SocketInputStream.read(SocketInputStream.java:141)
	at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
	- locked <0x000000066f2b0c70> (a java.io.BufferedInputStream)
	at java.io.FilterInputStream.read(FilterInputStream.java:83)
	at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:555)
	at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:834)
	at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:688)
	at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$$Lambda$3/1798010815.run(Unknown Source)
	at java.security.AccessController.doPrivileged(Native Method)
	at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:687)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
	- <0x000000066de42e10> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"JMX server connection timeout 29" #29 daemon prio=9 os_prio=31 tid=0x00007fe0fe8c0800 nid=0x9603 in Object.wait() [0x0000700004b2d000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at com.sun.jmx.remote.internal.ServerCommunicatorAdmin$Timeout.run(ServerCommunicatorAdmin.java:168)
	- locked <0x000000066e602030> (a [I)
	at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
	- None

"RMI Scheduler(0)" #28 daemon prio=9 os_prio=31 tid=0x00007fe0fe8c0000 nid=0x6d03 waiting on condition [0x0000700004a2a000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x000000066d3fc4b8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
	- None

"RMI TCP Accept-0" #26 daemon prio=9 os_prio=31 tid=0x00007fe0fe06e800 nid=0x9a03 runnable [0x0000700004824000]
   java.lang.Thread.State: RUNNABLE
	at java.net.PlainSocketImpl.socketAccept(Native Method)
	at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
	at java.net.ServerSocket.implAccept(ServerSocket.java:545)
	at java.net.ServerSocket.accept(ServerSocket.java:513)
	at sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(LocalRMIServerSocketFactory.java:52)
	at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:405)
	at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:377)
	at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
	- None

"Attach Listener" #24 daemon prio=9 os_prio=31 tid=0x00007fe0fe812800 nid=0x3d07 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"DestroyJavaVM" #23 prio=5 os_prio=31 tid=0x00007fe0aedc4800 nid=0x1103 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"Thread-1" #22 prio=5 os_prio=31 tid=0x00007fe09e01b000 nid=0x9c03 waiting for monitor entry [0x000070000461e000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at cn.lxh.java.ManyThread.Lock.deadlock.DeadLockTest.calLock21(DeadLockTest.java:49)
	- waiting to lock <0x000000066aefc610> (a java.lang.Object)
	- locked <0x000000066aefc620> (a java.lang.Object)
	at cn.lxh.java.ManyThread.Lock.deadlock.DeadLockTest.access$100(DeadLockTest.java:8)
	at cn.lxh.java.ManyThread.Lock.deadlock.DeadLockTest$2.run(DeadLockTest.java:28)
	at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
	- None

"Thread-0" #21 prio=5 os_prio=31 tid=0x00007fe0ff84a800 nid=0x9d03 waiting for monitor entry [0x000070000451b000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at cn.lxh.java.ManyThread.Lock.deadlock.DeadLockTest.calLock12(DeadLockTest.java:40)
	- waiting to lock <0x000000066aefc620> (a java.lang.Object)
	- locked <0x000000066aefc610> (a java.lang.Object)
	at cn.lxh.java.ManyThread.Lock.deadlock.DeadLockTest.access$000(DeadLockTest.java:8)
	at cn.lxh.java.ManyThread.Lock.deadlock.DeadLockTest$1.run(DeadLockTest.java:21)
	at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
	- None

"Service Thread" #20 daemon prio=9 os_prio=31 tid=0x00007fe0ff80f800 nid=0x6603 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"C1 CompilerThread11" #19 daemon prio=9 os_prio=31 tid=0x00007fe0aedc3800 nid=0x6503 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"C1 CompilerThread10" #18 daemon prio=9 os_prio=31 tid=0x00007fe09f008800 nid=0x6303 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"C1 CompilerThread9" #17 daemon prio=9 os_prio=31 tid=0x00007fe0de826800 nid=0xa103 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"C1 CompilerThread8" #16 daemon prio=9 os_prio=31 tid=0x00007fe0df008800 nid=0xa303 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"C2 CompilerThread7" #15 daemon prio=9 os_prio=31 tid=0x00007fe0fe812000 nid=0xa503 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"C2 CompilerThread6" #14 daemon prio=9 os_prio=31 tid=0x00007fe0fe85a000 nid=0xa703 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"C2 CompilerThread5" #13 daemon prio=9 os_prio=31 tid=0x00007fe0de825800 nid=0x6103 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"C2 CompilerThread4" #12 daemon prio=9 os_prio=31 tid=0x00007fe09e808800 nid=0x5f03 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"C2 CompilerThread3" #11 daemon prio=9 os_prio=31 tid=0x00007fe09e012000 nid=0x5d03 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"C2 CompilerThread2" #10 daemon prio=9 os_prio=31 tid=0x00007fe0df00a000 nid=0x5c03 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"C2 CompilerThread1" #9 daemon prio=9 os_prio=31 tid=0x00007fe0ae028800 nid=0x5b03 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"C2 CompilerThread0" #8 daemon prio=9 os_prio=31 tid=0x00007fe0aedb8800 nid=0x5903 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"JDWP Command Reader" #7 daemon prio=10 os_prio=31 tid=0x00007fe0de815000 nid=0x5703 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"JDWP Event Helper Thread" #6 daemon prio=10 os_prio=31 tid=0x00007fe0ce008800 nid=0x5503 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"JDWP Transport Listener: dt_socket" #5 daemon prio=10 os_prio=31 tid=0x00007fe0de808800 nid=0x4307 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"Signal Dispatcher" #4 daemon prio=9 os_prio=31 tid=0x00007fe0ff80e800 nid=0x4503 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"Finalizer" #3 daemon prio=8 os_prio=31 tid=0x00007fe0fe015000 nid=0x4d03 in Object.wait() [0x00007000030dc000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x000000066ab08ed8> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
	- locked <0x000000066ab08ed8> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)

   Locked ownable synchronizers:
	- None

"Reference Handler" #2 daemon prio=10 os_prio=31 tid=0x00007fe0fe012000 nid=0x3903 in Object.wait() [0x0000700002fd9000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x000000066ab06c00> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:502)
	at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
	- locked <0x000000066ab06c00> (a java.lang.ref.Reference$Lock)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

   Locked ownable synchronizers:
	- None

"VM Thread" os_prio=31 tid=0x00007fe0ee811800 nid=0x3703 runnable

"GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007fe0ff80d800 nid=0x1d07 runnable

"GC task thread#1 (ParallelGC)" os_prio=31 tid=0x00007fe0ff80e000 nid=0x2203 runnable

"GC task thread#2 (ParallelGC)" os_prio=31 tid=0x00007fe0fe81b800 nid=0x1f03 runnable

"GC task thread#3 (ParallelGC)" os_prio=31 tid=0x00007fe0fe81c000 nid=0x2a03 runnable

"GC task thread#4 (ParallelGC)" os_prio=31 tid=0x00007fe0fe81c800 nid=0x2b03 runnable

"GC task thread#5 (ParallelGC)" os_prio=31 tid=0x00007fe0fe81d000 nid=0x2d03 runnable

"GC task thread#6 (ParallelGC)" os_prio=31 tid=0x00007fe0fe81e000 nid=0x2f03 runnable

"GC task thread#7 (ParallelGC)" os_prio=31 tid=0x00007fe0fe81e800 nid=0x5303 runnable

"GC task thread#8 (ParallelGC)" os_prio=31 tid=0x00007fe0fe81f000 nid=0x3103 runnable

"GC task thread#9 (ParallelGC)" os_prio=31 tid=0x00007fe0fe81f800 nid=0x3303 runnable

"GC task thread#10 (ParallelGC)" os_prio=31 tid=0x00007fe0fe820800 nid=0x3403 runnable

"GC task thread#11 (ParallelGC)" os_prio=31 tid=0x00007fe0fe821000 nid=0x5003 runnable

"GC task thread#12 (ParallelGC)" os_prio=31 tid=0x00007fe0fe821800 nid=0x4f03 runnable

"VM Periodic Task Thread" os_prio=31 tid=0x00007fe0de812000 nid=0x9e03 waiting on condition

JNI global references: 5087


Found one Java-level deadlock:
=============================
"Thread-1":
  waiting to lock monitor 0x00007fe0de009808 (object 0x000000066aefc610, a java.lang.Object),
  which is held by "Thread-0"
"Thread-0":
  waiting to lock monitor 0x00007fe0de00d8a8 (object 0x000000066aefc620, a java.lang.Object),
  which is held by "Thread-1"

Java stack information for the threads listed above:
===================================================
"Thread-1":
	at cn.lxh.java.ManyThread.Lock.deadlock.DeadLockTest.calLock21(DeadLockTest.java:49)
	- waiting to lock <0x000000066aefc610> (a java.lang.Object)
	- locked <0x000000066aefc620> (a java.lang.Object)
	at cn.lxh.java.ManyThread.Lock.deadlock.DeadLockTest.access$100(DeadLockTest.java:8)
	at cn.lxh.java.ManyThread.Lock.deadlock.DeadLockTest$2.run(DeadLockTest.java:28)
	at java.lang.Thread.run(Thread.java:748)
"Thread-0":
	at cn.lxh.java.ManyThread.Lock.deadlock.DeadLockTest.calLock12(DeadLockTest.java:40)
	- waiting to lock <0x000000066aefc620> (a java.lang.Object)
	- locked <0x000000066aefc610> (a java.lang.Object)
	at cn.lxh.java.ManyThread.Lock.deadlock.DeadLockTest.access$000(DeadLockTest.java:8)
	at cn.lxh.java.ManyThread.Lock.deadlock.DeadLockTest$1.run(DeadLockTest.java:21)
	at java.lang.Thread.run(Thread.java:748)

Found 1 deadlock.

从上述信息可以看出使用 jstack ，可以很方便地排查出代码中出现“deadlock”（死锁）的问题。

JVisualVM

出了上面的命令行工具，还有可视化的工具JVisualVM，启动后的界面如下：
JVisualVM

从上图中，可以清晰的看出来，发生了一个死锁，另外还可以在IDEA中的安装插件使用

JVM调优

JVM 调优主要是根据实际的硬件配置信息重新设置 JVM 参数来进行调优的，例如，硬件的内存配置很高，但 JVM 因为是默认参数，所以最大内存和初始化堆内存很小，这样就不能更好地利用本地的硬件优势了。因此，需要调整这些参数，让 JVM 在固定的配置下发挥最大的价值。

JVM 常见调优参数包含以下这些：

  • Xmx，设置最大堆内存大小；
  • Xms，设置初始堆内存大小；
  • XX:MaxNewSize，设置新生代的最大内存；
  • XX:MaxTenuringThreshold，设置新生代对象经过一定的次数晋升到老生代；
  • XX:PretrnureSizeThreshold，设置大对象的值，超过这个值的对象会直接进入老生代；
  • XX:NewRatio，设置分代垃圾回收器新生代和老生代内存占比；
  • XX:SurvivorRatio，设置新生代 Eden、Form Survivor、To Survivor 占比。

# JVM