默认情况下, JVM 是不会输出 verbose GC log 的, 只有设置相关 flag 之后才会写到文件. 并且根据各种 flag 参数的设置不同, 输出的详细程度也不一样. 下面这些都是与 verbose GC log 相关的参数.

1. -Xloggc:verboseGC.log
   设置 GC log 文件名, 这个必须设置, 才能看到日志文件.
2. -XX:+PrintGC 打印 GC 日志
3. -XX:+PrintGCDetails 输出更详细的 GC 日志, 包括每次年轻代, 总 heap size 大小 GC 前后变化, 以及消耗 CPU 的时间.

与log 文件 rotate 和文件大小, 个数相关的三个参数:

1. -XX:+UseGCLogFileRotation log 循环写, 而不是一直写到一个文件
2. -XX:NumberOfGCLogFiles=5 可循环写的文件个个数, 这里设置共5个
3. -XX:GCLogFileSize=2000k 每个可循环文件的大小, 这里设置是2M. 当前正在写的文件名有一个 current, 用来区别不是正在写的. 比如可能的文件如下:

   verboseGC.log.0
   verboseGC.log.1
   verboseGC.log.2.current
   verboseGC.log.3
   verboseGC.log.4

log 文件中显示与时间相关的参数:
-XX:+PrintGCTimeStamps
-XX:+PrintGCDateStamps

一个典型的 verbose GC log 如下:

Java HotSpot(TM) 64-Bit Server VM (25.141-b15) for bsd-amd64 JRE (1.8.0_141-b15), built on Jul 12 2017 04:35:23 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
Memory: 4k page, physical 16777216k(317124k free)

/proc/meminfo:

CommandLine flags: -XX:GCLogFileSize=204800 -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:NumberOfGCLogFiles=5 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseGCLogFileRotation -XX:+UseParallelGC 
2019-07-05T20:39:58.844+0700: 0.374: [GC (Allocation Failure) [PSYoungGen: 5632K->496K(6144K)] 5632K->2232K(19968K), 0.0028539 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-07-05T20:39:58.935+0700: 0.466: [GC (Allocation Failure) [PSYoungGen: 6128K->480K(6144K)] 7864K->3361K(19968K), 0.0017132 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-07-05T20:39:59.028+0700: 0.559: [GC (Allocation Failure) [PSYoungGen: 6112K->480K(6144K)] 8993K->4240K(19968K), 0.0014840 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]  

首先, 在每个文件的头部, 都会有当前 JVM 的一些信息, 以及一些 JVM 启动参数, 之后就是详细的 GC 日志.

在分析应用响应变慢, CPU 使用率比较高, 死锁等问题时, thread dump 都非常有用. 那么怎么样才能获取一个Java 应用的 thread dump 呢?

1. 如果有 JDK, 那么 JDK 再带的小工具能非常快的做出 thread dump.
   首先, 使用 JDK bin 目录下的 jps 命令, 能非常快的确认正在运行的 java 进程, 打印进程 id.

   33205 MyApp
   93946 Jps

上面的输出当中, 93946是 jps 命令本身的进程 id, 因为它也是一个 java 进程;
得到进程 ID 之后, 有下面这2种方法, 可以获取 thread dump:
1. 使用 jstack 命令
   jstack -l  <pid> > <file-path>
   ```jstack -l 33205 > /tmp/threadDump.txt```

2. 使用 jcmd 命令
   jcmd <pid> Thread.print > <file-path>
   ```jcmd 33205 Thread.print /tmp/threadDump.txt```

1. 在某些生产环境, 可能只安装 JRE, 没有安装 JDK, 那么可以使用 kill -3 <pid> 命令, 给Java 进程发信号, 让它产生 thread dump.
2. 如果你是在一个桌面系统, 可以使用JDK 自带的 GUI 工具: Java Mission Control 或者 JVisualVM.
3. 如果想使用编程的方式, 可以使用 ThreadMXBean, 它能 dump 出 Java 进程的所有线程.

    ThreadMXBean threadMxBean = ManagementFactory.getThreadMXBean();
        for (ThreadInfo ti : threadMxBean.dumpAllThreads(true, true)) {
            System.out.print(ti.getThreadId());
            System.out.print(ti.getThreadName());
            System.out.print(ti.getThreadState());
            System.out.print(ti.getStackTrace());
            System.out.print(ti.getLockInfo());
        }
}

1. 在某些 Windows 桌面环境, 如果你是通过命令行启动, 可以通过 Ctrl + Break 来生成 thread dump

jstat 用来显示 JVM 的某些指标的统计信息, 可以每隔固定时间采集一次,设置共采集多少次. 主要用来采集 GC 和运行时编译相关的统计信息.

比如下面诊断为什么系统一直 full GC, 最后发现是人为的调用 System.gc().

jstat -gccause 332 3s 5 //332 是进程id, 每 3s 采集一次, 共采集 5 次z

下面这个例子采集 GC 的统计信息, S0, S1 分别代表 survivor 0 和 survivor 1, E 代表 Eden, O 代表 Old, P 代表 Permermanent, C 代表 Capacity, U 代表 Used. YGC 和 FGC 分别代表 Young generation 和 Full generation GC, 后面的 T 代表花费的的时间 (Time)

jstat -gc 332 3s 5

另外 -options 显示所有可以采集的项目

$ ./jstat -options
-class
-compiler
-gc
-gccapacity
-gccause
-gcnew
-gcnewcapacity
-gcold
-gcoldcapacity
-gcpermcapacity
-gcutil
-printcompilation

jps 相当于 Linux ps命令, 不过它只显示 java 进程. 通常我们我们为了做 thread dump, heap dump 的第一步就是找到这个进程 id, jps 能很快的帮我们找到这个进程 id. 默认情况下 jps 只会显示当前用户的 java 进程, 如果要查看的应用程序是属于另外一个用户的进程, 那么要切换到另外一个用户, 或者使用 sudo jps.

workstation:~ xiatian$ jps
10824 Jps
95833 gcviewer-1.36-SNAPSHOT.jar

// -v 显示启动 jvm 时候的参数

workstation:~ xiatian$ jps -v 
10833 Jps -Dapplication.home=/Library/Java/JavaVirtualMachines/jdk-11.0.3.jdk/Contents/Home -Xms8m -Djdk.module.main=jdk.jcmd
95833 gcviewer-1.36-SNAPSHOT.jar

//显示 main 函数的全包名, 如果是 jar 的话, 显示全路径

workstation:~ xiatian$ jps -l
10836 jdk.jcmd/sun.tools.jps.Jps
95833 /Users/xiatian/Desktop/gcviewer-1.29/gcviewer-1.36-SNAPSHOT.jar

1. cpu 使用率;
2. 内存使用率;
3. 磁盘使用情况;

4. 网络使用情况;

   • JVM 层面
5. Jvm cpu 使用情况;
6. gc overhead;
7. gc count;
8. gc 每次回收后的使用情况;
9. jfr 的重要指标;
10. Jvm memory available;

11. oom error count;

    • 应用框架层面
12. 作为 service client 调用下游时候的 成功/失败次数, 平均时间;

13. 调用外部数据存储的 成功/失败次数, 平均时间;

    • 应用层面
14. tps/ops;
15. transaction time;
16. 5xx count;
17. 4xx count;
18. app busy threads;
19. app total thread count;
20. error count;