JVM调优(三)JVM内存信息查看与分析

JVM调优(三)JVM内存信息查看与分析

查看堆内存的使用情况jstat

  • jstat可以查看堆内存各个部分的使用量, 以及加载类的数量

  • 命令格式jstat [-命令选项] [vmid] [间隔毫秒] [查询次数]

  • 示例: 查看class加载统计
    • Loaded表示加载class的数量
    • Bytes表示占用空间大小
    • Unloaded表示未加载数量
    • Time表示加载耗时
$ java -jar ZhiHuPicSpider.jar
...
$ jps -l
5648 ZhiHuPicSpider.jar
14212 sun.tools.jps.Jps
$jstat -class 5648
Loaded    Bytes      Unloaded  Bytes     Time
 7855    14437.6        0       0.0      3.84
  • 示例: 查看gc详细信息, 每间隔1000ms打印一次, 共打印3次
    • S0C代表第一个survivor区的大小(KB)
    • S1C代表第二个survivor区的大小(KB)
    • S0U代表第一个survivor区的使用大小(KB)
    • S1U代表第二个survivor区的使用大小(KB)
    • EC代表Eden区的大小(KB)
    • EU代表Eden区的使用大小(KB)
    • OC代表老年代的大小(KB)
    • OU代表老年代的使用大小(KB)
    • MC代表方法区的大小(KB)
    • MU代表方法区的使用大小(KB)
    • CCSC代表压缩类空间的大小(KB)
    • CCSU代表压缩类空间的使用大小(KB)
    • YGC代表年轻代发生GC的次数
    • YGCT代表年轻代GC的消耗时间
    • FGC代表老年代发生GC的次数
    • FGCT代表老年代GC的消耗时间
    • GCT代表GC消耗的总时间
$ java -jar ZhiHuPicSpider.jar
...
$ jps -l
5296 sun.tools.jps.Jps
13084 ZhiHuPicSpider.jar
$ jstat -gc 13084 1000 3
 S0C     S1C     S0U    S1U      EC       EU       OC         OU       MC      MU     CCSC   CCSU       YGC   YGCT   FGC     FGCT     GCT
13312.0 13824.0  0.0   8221.1 203264.0  8645.3   93696.0    18462.1   43008.0 41320.2 5632.0 5318.3      9    0.057   2      0.098    0.155
13312.0 13824.0  0.0   8221.1 203264.0  8645.3   93696.0    18462.1   43008.0 41320.2 5632.0 5318.3      9    0.057   2      0.098    0.155
13312.0 13824.0  0.0   8221.1 203264.0  8645.3   93696.0    18462.1   43008.0 41320.2 5632.0 5318.3      9    0.057   2      0.098    0.155

注意, 此处显示两个survivor区大小不一致是由于JVM默认开启survivor区大小自动变化的参数-XX:+UseAdaptiveSizePolicy


查看内存的详细使用情况jmap

jstat可以对JVM堆内存进行统计分析, 而jmap可以获取更详细的内容, 比如内存使用情况的汇总, 对内存溢出的定位与分析.

  • 查看堆内存的使用情况jmap -heap <进程id>

$ java -jar ZhiHuPicSpider.jar
...
$ jps -l
5296 sun.tools.jps.Jps
13084 ZhiHuPicSpider.jar
$ jmap -heap 13084
Attaching to process ID 13084, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.181-b13

using thread-local object allocation.
Parallel GC with 8 thread(s)

Heap Configuration: # 堆内存配置信息
   MinHeapFreeRatio         = 0
   MaxHeapFreeRatio         = 100
   MaxHeapSize              = 2118123520 (2020.0MB) # 堆内存最大大小
   NewSize                  = 44564480 (42.5MB) # 年轻代初始大小
   MaxNewSize               = 705691648 (673.0MB) # 年轻代最大大小
   OldSize                  = 89653248 (85.5MB) # 老年代大小
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage: # 堆内存的使用情况
PS Young Generation # 年轻代
Eden Space: # Eden区
   capacity = 208142336 (198.5MB)
   used     = 8852760 (8.442649841308594MB)
   free     = 199289576 (190.0573501586914MB)
   4.253224101414909% used
From Space: # survivor区1
   capacity = 14155776 (13.5MB)
   used     = 8418432 (8.0284423828125MB)
   free     = 5737344 (5.4715576171875MB)
   59.469943576388886% used
To Space: # survivor区2
   capacity = 13631488 (13.0MB)
   used     = 0 (0.0MB)
   free     = 13631488 (13.0MB)
   0.0% used
PS Old Generation # 老年代
   capacity = 95944704 (91.5MB)
   used     = 18905208 (18.02941131591797MB)
   free     = 77039496 (73.47058868408203MB)
   19.70427466220543% used

21415 interned Strings occupying 2607000 bytes.
  • 查看堆内存中对象的数量以及大小

    • 查看所有对象, 包括活跃的和不活跃的: jmap -histo <进程id> | more
    • 查看活跃对象: jmap -histo:live <进程id> | more
$ jmap -histo 13084 | more

 num     #instances         #bytes  class name
----------------------------------------------
   1:          4331       10984224  [I
   2:         65122        8976592  [C
   3:          6615        4442000  [B
   4:         63409        1521816  java.lang.String
   5:         16433        1446104  java.lang.reflect.Method
   6:          8461         946656  java.lang.Class
   7:         29317         938144  java.util.concurrent.ConcurrentHashMap$Node
   8:          9248         472920  [Ljava.lang.Object;
   9:         10578         423120  java.util.LinkedHashMap$Entry
  10:         12505         400160  java.util.HashMap$Node
-- More --
对象说明:
B	byte
C	char
D	double
F	float
I	int
J	long
Z	boolean
[	数组, 比如[I代表int[]
[L+类名	其他对象
  • 将内存快照dump到文件中

    • 命令格式jmap -dump:format=b,file=fileName <进程id>

$ java -jar ZhiHuPicSpider.jar
...
$ jps -l
5296 sun.tools.jps.Jps
13084 ZhiHuPicSpider.jar
$ pwd
$ /home/test/
$ jmap -dump:format=b,file=mydump.dat 13084
Dumping heap to /home/test/mydump.dat ...
Heap dump file created

通过jhat对dump文件进行分析

$ jhat -port 9999 mydump.dat
Reading from mydump.dat...
Dump file created Sun Dec 19 14:21:12 CST 2021
Snapshot read, resolving...
Resolving 1085413 objects...
Chasing references, expect 217 dots.........................................................................................................................................................................................................................
Eliminating duplicate references.........................................................................................................................................................................................................................
Snapshot resolved.
Started HTTP server on port 9999
Server is ready.

image.png
页面中以包为分组列出了内存中所有的对象信息
在页面最下面的Execute Object Query Language (OQL) query可以进行某个类型的对象查询:
image.png


通过MAT工具对dump文件进行分析

MAT是一个基于eclips的内存分析工具, 可以帮助我们查找内存泄露和减少内存消耗(https://www.eclipse.org/mat)

  • 下载解压MAT工具
    image.png
  • 运行MemoryAnalyzer.exe
    image.png
  • 选择内存泄露分析报告
    image.png
  • 在总览页面主要关注实例信息统计项和依赖树分析项
    image.png
  • 在问题报告页主要展示了MAT分析出的可能存在的问题
    image.png

内存溢出定位与分析

  • 编写代码模拟内存溢出

向List集合中添加100万个字符串,每个字符串由1000个UUID组成。如果程序能够正常执行,最后打印OK

import java.util.ArrayList;
import java.util.List;
import java.util.UUID;

public class TestJvmOutOfMemory {
    public static void main(String[] args) {
        List<Object> list = new ArrayList<>();
        for (int i = 0; i < 10000000; i++) {
            String str = "";
            for (int j = 0; j < 1000; j++) {
                str += UUID.randomUUID().toString();
            }
            list.add(str);
        }
        System.out.println("OK");
    }
}
  • 修改此程序运行时的堆内存大小

使用idea运行此程序, 设置JVM运行参数, 设置一个较小的堆内存
(或者打jar包, 使用java -jar命令时指定-XX参数)

-Xms8m -Xmx8m -XX:+HeapDumpOnOutOfMemoryError
  • 运行测试

当发生内存溢出时, 抛出OOM异常, 同时生成内存快照
image.png

java.lang.OutOfMemoryError: Java heap space
Dumping heap to java_pid5348.hprof ...
Heap dump file created [8137186 bytes in 0.032 secs]
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
at java.util.Arrays.copyOf(Arrays.java:3332)
at
java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:124)
at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:448)
at java.lang.StringBuilder.append(StringBuilder.java:136)
at cn.itcast.jvm.TestJvmOutOfMemory.main(TestJvmOutOfMemory.java:14)
Process finished with exit code 1
  • 将dump的内存快照文件导入MAT进行内存泄露分析

可以看到绝大部分内存都被Object[]数组占用, 比较可疑
image.png

  • 查看Details可以看到集合中存储了大量UUID字符串

image.png


JVM线程分析jstack

有些时候我们需要查看下jvm中的线程执行情况,比如,发现服务器的CPU的负载突然增高了、出现了死锁、死循, 由于程序是正常运行的,没有任何的输出,从日志方面也看不出什么问题,所以就需要看下jvm的内部线程的执行情况,然后再进行分析查找出原因。

  • jstack可以将正在运行的JVM的线程快照打印出来, 命令格式jstack 进程id

$ jps -l
7536 sun.tools.jps.Jps
14532 ZhiHuPicSpider.jar
$ jstack 14532
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.181-b13 mixed mode):

"TimerQueue" #42 daemon prio=5 os_prio=0 tid=0x0000000020008800 nid=0x4e4 waiting on condition [0x000000002506e000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000e2060bf8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.DelayQueue.take(DelayQueue.java:211)
        at javax.swing.TimerQueue.run(TimerQueue.java:174)
        at java.lang.Thread.run(Thread.java:748)

"DestroyJavaVM" #40 prio=5 os_prio=0 tid=0x0000000020009000 nid=0x2380 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"AWT-EventQueue-0" #38 prio=6 os_prio=0 tid=0x0000000020007800 nid=0x321c waiting on condition [0x00000000252af000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x000000008258ca30> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

......

"VM Thread" os_prio=2 tid=0x0000000018108000 nid=0x1a34 runnable

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00000000030a8000 nid=0x3a5c runnable

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00000000030a9800 nid=0x14c4 runnable

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00000000030ab800 nid=0x199c runnable

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00000000030ad000 nid=0x340c runnable

"GC task thread#4 (ParallelGC)" os_prio=0 tid=0x00000000030af000 nid=0x3a74 runnable

"GC task thread#5 (ParallelGC)" os_prio=0 tid=0x00000000030b1800 nid=0x2594 runnable

"GC task thread#6 (ParallelGC)" os_prio=0 tid=0x00000000030b4800 nid=0x3674 runnable

"GC task thread#7 (ParallelGC)" os_prio=0 tid=0x00000000030b5800 nid=0x1094 runnable

"VM Periodic Task Thread" os_prio=2 tid=0x000000001a127800 nid=0x2084 waiting on condition

JNI global references: 1047
  • JVM中线程的状态

    • 初始态(NEW)

      • 创建一个Thread对象,但还未调用start()启动线程时,线程处于初始态。
    • 运行态(RUNNABLE)

      • 在Java中,运行态包括 就绪态 和 运行态。
      • 就绪态
        • 该状态下的线程已经获得执行所需的所有资源,只要CPU分配执行权就能运行。
        • 所有就绪态的线程存放在就绪队列中。
      • 运行态
        • 获得CPU执行权,正在执行的线程。
        • 由于一个CPU同一时刻只能执行一条线程,因此每个CPU每个时刻只有一条运行态的线程。
    • 阻塞态(BLOCKED)

      • 当一条正在执行的线程请求某一资源失败时,就会进入阻塞态。
      • 而在Java中,阻塞态专指请求锁失败时进入的状态。
      • 由一个阻塞队列存放所有阻塞态的线程。
      • 处于阻塞态的线程会不断请求资源,一旦请求成功,就会进入就绪队列,等待执行。
    • 等待态(WAITING)

      • 当前线程中调用wait、join、park函数时,当前线程就会进入等待态。
      • 也有一个等待队列存放所有等待态的线程。
      • 线程处于等待态表示它需要等待其他线程的指示才能继续运行。
      • 进入等待态的线程会释放CPU执行权,并释放资源(如:锁)
    • 超时等待态(TIMED_WAITING)

      • 当运行中的线程调用sleep(time)、wait、join、parkNanos、parkUntil时,就会进入该状态;
      • 它和等待态一样,并不是因为请求不到资源,而是主动进入,并且进入后需要其他线程唤醒;
      • 进入该状态后释放CPU执行权 和 占有的资源。
      • 与等待态的区别:到了超时时间后自动进入阻塞队列,开始竞争锁。
    • 终止态(TERMINATED)

      • 线程执行结束后的状态。
        image.png
  • 构造死锁

编写代码, 让两个线程互相等待获取对方已经拿到的锁, 造成死锁

public class TestDeadLock {
    private static String A = "aaa";
    private static String B = "bbb";

    public static void main(String[] args) {
        new Thread(new ThreadA()).start();
        new Thread(new ThreadB()).start();
    }

    static class ThreadA implements Runnable {
        @Override
        public void run() {
            synchronized (A) {
                System.out.println("ThreadA 获取到 A 的锁");
                try {
                    // ThreadA休眠2秒, 让ThreadB拿到 B 的锁
                    Thread.sleep(2000L);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
                synchronized (B) {
                    System.out.println("ThreadA 获取到 B 的锁");
                }
            }
        }
    }

    static class ThreadB implements Runnable {
        @Override
        public void run() {
            synchronized (B) {
                System.out.println("ThreadB 获取到 B 的锁");
                try {
                    // ThreadB休眠2秒, 让ThreadA拿到 A 的锁
                    Thread.sleep(2000L);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
                synchronized (A) {
                    System.out.println("ThreadB 获取到 A 的锁");
                }
            }
        }
    }
}
  • 分析死锁线程

运行构造好的死锁代码, 使用jstack进行分析, 在输出的信息中, 提示发现了一个死锁
可以看到:

- ThreadB已经获取了<0x00000000d6119268>锁, 等待获取<0x00000000d6119238>锁
- ThreadA已经获取了<0x00000000d6119238>锁, 等待获取<0x00000000d6119268>锁
- 两个线程互相等待对方释放锁, 造成了死锁
$ jps -l
6708 sun.tools.jps.Jps
7604 cn.zack.controller.TestDeadLock
$ jstack 7604
2021-12-20 10:21:59
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.181-b13 mixed mode):

"DestroyJavaVM" #14 prio=5 os_prio=0 tid=0x0000000003154800 nid=0x1908 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Thread-1" #13 prio=5 os_prio=0 tid=0x000000001aee9000 nid=0x1fd4 waiting for monitor entry [0x000000001b88f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at cn.zack.controller.TestDeadLock$ThreadB.run(TestDeadLock.java:42)
        - waiting to lock <0x00000000d6119238> (a java.lang.String)
        - locked <0x00000000d6119268> (a java.lang.String)
        at java.lang.Thread.run(Thread.java:748)

"Thread-0" #12 prio=5 os_prio=0 tid=0x000000001a460000 nid=0x346c waiting for monitor entry [0x000000001b78f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at cn.zack.controller.TestDeadLock$ThreadA.run(TestDeadLock.java:24)
        - waiting to lock <0x00000000d6119268> (a java.lang.String)
        - locked <0x00000000d6119238> (a java.lang.String)
        at java.lang.Thread.run(Thread.java:748)

"Service Thread" #11 daemon prio=9 os_prio=0 tid=0x000000001a3dc800 nid=0xf30 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread3" #10 daemon prio=9 os_prio=2 tid=0x000000001a32f800 nid=0x27e8 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread2" #9 daemon prio=9 os_prio=2 tid=0x000000001a327000 nid=0xdf0 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #8 daemon prio=9 os_prio=2 tid=0x000000001a324000 nid=0x35c4 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #7 daemon prio=9 os_prio=2 tid=0x000000001a31f000 nid=0x598 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Monitor Ctrl-Break" #6 daemon prio=5 os_prio=0 tid=0x000000001a31d000 nid=0x1c18 runnable [0x000000001a88e000]
   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 sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
        at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
        at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
        - locked <0x00000000d61d95c0> (a java.io.InputStreamReader)
        at java.io.InputStreamReader.read(InputStreamReader.java:184)
        at java.io.BufferedReader.fill(BufferedReader.java:161)
        at java.io.BufferedReader.readLine(BufferedReader.java:324)
        - locked <0x00000000d61d95c0> (a java.io.InputStreamReader)
        at java.io.BufferedReader.readLine(BufferedReader.java:389)
        at com.intellij.rt.execution.application.AppMainV2$1.run(AppMainV2.java:49)

"Attach Listener" #5 daemon prio=5 os_prio=2 tid=0x000000001a121000 nid=0x163c waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

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

"Finalizer" #3 daemon prio=8 os_prio=1 tid=0x000000001a0b0800 nid=0x2018 in Object.wait() [0x000000001a58e000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000d5f08ed0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
        - locked <0x00000000d5f08ed0> (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)

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

"VM Thread" os_prio=2 tid=0x00000000181c8800 nid=0xaec runnable

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x000000000316a800 nid=0x3520 runnable

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x000000000316c000 nid=0x2794 runnable

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x000000000316d800 nid=0x156c runnable

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x000000000316f000 nid=0x3358 runnable

"GC task thread#4 (ParallelGC)" os_prio=0 tid=0x0000000003171800 nid=0x1a98 runnable

"GC task thread#5 (ParallelGC)" os_prio=0 tid=0x0000000003172800 nid=0x1934 runnable

"GC task thread#6 (ParallelGC)" os_prio=0 tid=0x0000000003176800 nid=0x16f8 runnable

"GC task thread#7 (ParallelGC)" os_prio=0 tid=0x0000000003178000 nid=0x5f4 runnable

"VM Periodic Task Thread" os_prio=2 tid=0x000000001a462800 nid=0x1e5c waiting on condition

JNI global references: 12


Found one Java-level deadlock:
=============================
"Thread-1":
  waiting to lock monitor 0x00000000181d0d58 (object 0x00000000d6119238, a java.lang.String),
  which is held by "Thread-0"
"Thread-0":
  waiting to lock monitor 0x00000000181d35e8 (object 0x00000000d6119268, a java.lang.String),
  which is held by "Thread-1"

Java stack information for the threads listed above:
===================================================
"Thread-1":
        at cn.zack.controller.TestDeadLock$ThreadB.run(TestDeadLock.java:42)
        - waiting to lock <0x00000000d6119238> (a java.lang.String)
        - locked <0x00000000d6119268> (a java.lang.String)
        at java.lang.Thread.run(Thread.java:748)
"Thread-0":
        at cn.zack.controller.TestDeadLock$ThreadA.run(TestDeadLock.java:24)
        - waiting to lock <0x00000000d6119268> (a java.lang.String)
        - locked <0x00000000d6119238> (a java.lang.String)
        at java.lang.Thread.run(Thread.java:748)

Found 1 deadlock.