JVM业务

JDK命令

jvm调优监控工具jps、jstack、jmap、jhat、jstat使用详解 - 好奇成传奇 - 博客园 (cnblogs.com)

名称	主要功能
jps	JVM Process Status Tool，显示指定系统内所有HotSpot虚拟机进程
jstat	JVM Statistics Minitoring Tool，用于收集HotSpot虚拟机各方面的运行数据
jinfo	Configuration Info for Java，显示虚拟机配置信息
jmap	Memory Map for Java，生成虚拟机的内存转储快照（heapdump）文件
jhat	(Java Heap Analysis Tool) / JVM Heap Dump Browser，用于分析heapdump文件，它会建立一个HTTP/HTML服务器，让用户可以在浏览器上查看分析结果
jstack	Stack Trace for Java，显示虚拟机的线程快照
jcmd

jstack, jstat, jps, jinfo, jmap jhat

JVM内存模型（JMM）

工作内存（高速缓存，寄存器）和主内存

工作内存（虚拟机栈，本地方法栈）和主内存（堆和方法区）

MESI协议

MESI是一种比较常用的缓存一致性协议，MESI表示缓存行的四种状态，分别是：
1、M(Modify) 表示共享数据只缓存在当前 CPU 缓存中，并且是被修改状态，也就是缓存的数据和主内存中的数据不一致
2、E(Exclusive) 表示缓存的独占状态，数据只缓存在当前CPU缓存中，并且没有被修改
3、S(Shared) 表示数据可能被多个 CPU 缓存，并且各个缓存中的数据和主内存数据一致
4、I(Invalid) 表示缓存已经失效
在 MESI 协议中，每个缓存的缓存控制器不仅知道自己的读写操作，而且也监听(snoop)其它CPU的读写操作。
对于 MESI 协议，从 CPU 读写角度来说会遵循以下原则：
CPU读请求：缓存处于 M、E、S 状态都可以被读取，I 状态CPU 只能从主存中读取数据
CPU写请求：缓存处于 M、E 状态才可以被写。对于S状态的写，需要将其他CPU中缓存行置为无效才行。

JVM – 专栏

(13条消息) JVM从入门到精通_VectorUx的博客-CSDN博客

垃圾回收器

CMS

终于把CMS垃圾收集器搞懂了~ - 掘金 (juejin.cn)

G1

看完这篇G1垃圾收集器的总结就足以吊打面试官了~ - 掘金 (juejin.cn)

日志分析

https://juejin.cn/post/7029130033268555807

Serial GC

Java HotSpot(TM) 64-Bit Server VM (25.201-b09) for windows-amd64 JRE (1.8.0_201-b09), built on Dec 15 2018 18:36:39 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16657944k(1083240k free), swap 33750228k(6246880k free)
CommandLine flags: 
-XX:InitialHeapSize=536870912 //初始化堆内存
-XX:MaxHeapSize=536870912     //最大堆内存
-XX:+PrintGC 
-XX:+PrintGCDateStamps 
-XX:+PrintGCDetails 
-XX:+PrintGCTimeStamps 
-XX:-UseAdaptiveSizePolicy 
-XX:+UseCompressedClassPointers 
-XX:+UseCompressedOops 
-XX:-UseLargePagesIndividualAllocation
-XX:+UseSerialGC 
----------------------Minor GC----------------------------
2021-09-09T14:44:04.813+0800: 0.163: [GC (Allocation Failure) 2021-09-09T14:44:04.813+0800: 0.163: 
[DefNew: 139776K->17472K(157248K), 0.0164545 secs] 139776K->45787K(506816K), 0.0165501 secs] [Times: user=0.00 sys=0.02, real=0.02 secs] 
2021-09-09T14:44:04.853+0800: 0.203: [GC (Allocation Failure) 2021-09-09T14:44:04.853+0800: 0.203:
[DefNew: 157248K->17471K(157248K), 0.0192998 secs] 185563K->84401K(506816K), 0.0193485 secs] [Times: user=0.02 sys=0.01, real=0.02 secs] 
-----------------------Full GC----------------------------
2021-09-09T14:44:05.240+0800: 0.589: [GC (Allocation Failure) 2021-09-09T14:44:05.240+0800: 0.589: 
[DefNew: 157148K->157148K(157248K), 0.0000289 secs]2021-09-09T14:44:05.240+0800: 0.589: 
[Tenured: 341758K->308956K(349568K), 0.0459961 secs] 498907K->308956K(506816K),
[Metaspace: 2608K->2608K(1056768K)], 0.0460956 secs] [Times: user=0.05 sys=0.00, real=0.05 secs] 
----------------------以下为将Xmx和Xms设置为256m后新产生的Full GC日志----------------------------------
2021-09-09T20:43:46.806+0800: 0.340: [GC (Allocation Failure) 2021-09-09T20:43:46.806+0800: 0.340: 
[DefNew: 69734K->69734K(78656K), 0.0000272 secs]2021-09-09T20:43:46.806+0800: 0.340: 
[Tenured: 167334K->174631K(174784K), 0.0251452 secs] 237068K->181953K(253440K), 
[Metaspace: 2760K->2760K(1056768K)], 0.0253029 secs] [Times: user=0.02 sys=0.00, real=0.03 secs] 

2021-09-09T20:43:46.841+0800: 0.375: [Full GC (Allocation Failure) 2021-09-09T20:43:46.841+0800: 0.375: 
[Tenured: 174631K->174502K(174784K), 0.0228937 secs] 252975K->195967K(253440K),
[Metaspace: 2760K->2760K(1056768K)], 0.0230051 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

GC-回收类型、GC出发原名、收集器名称、(回收区域)回收前后内存变化，堆内存变化、回收耗时:

• 2021-09-09T14:44:04.813-GC事件开始的时间点。+0800表示当前时区为东八区，这只是一个标识。0.163是GC事件相对于JVM启动时间的间隔，单位是秒
• GC - 用来区分Minor GC还是Full GC的标志。GC表明这是一次小型GC（Minor GC），即年轻代GC。Allocation Failure 表示触发GC的原因。本次GC事件是由于对象分配失败，即年轻代中没有空间来存放新生成的对象引起的。
• DefNew表示垃圾收集器的名称。这个名称表示：年轻到使用的单线程、标记-复制、STW的垃圾收集器。139776K->17472K 表示在垃圾收集之前和之后的年轻代使用量。(157248K) 表示年轻代的总空间大小。分析可得，GC之后年轻代使用率为11%。
• 139776K->45787K 表示在垃圾收集前后整个堆内存的使用情况，(506816K)表示整个堆的大小
• 0.0165501 secs - GC事件的持续时间，单位：秒
• [Times: user=0.00 sys=0.02, real=0.02 secs] 表示此次GC事件的持续时间，通过三个部分来衡量：user 表示所有GC线程消耗的CPU时间；sys 表示系统调用和系统等待事件消耗的时间；real表示应用程序暂停的时间

Parallel GC

---------------------第一部分------------------------------
Java HotSpot(TM) 64-Bit Server VM (25.201-b09) for windows-amd64 JRE (1.8.0_201-b09), built on Dec 15 2018 18:36:39 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16645364k(7836692k free), swap 19431936k(6065040k free)
CommandLine flags: 
-XX:InitialHeapSize=536870912 
-XX:MaxHeapSize=536870912
-XX:+PrintGC
-XX:+PrintGCDateStamps
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:-UseAdaptiveSizePolicy
-XX:+UseCompressedClassPointers
-XX:+UseCompressedOops
-XX:-UseLargePagesIndividualAllocation
-XX:+UseParallelGC
---------------------第二部分------------------------------
2021-09-09T22:08:14.204+0800: 0.393:
[GC (Allocation Failure) 
[PSYoungGen: 153077K->21497K(153088K)] 446120K->355171K(502784K), 0.0096928 secs] [Times: user=0.05 sys=0.11, real=0.01 secs] 
---------------------第三部分------------------------------
..........中间省略部分............
2021-09-09T22:08:14.214+0800: 0.403: [Full GC (Ergonomics)
[PSYoungGen: 21497K->0K(153088K)] 
[ParOldGen: 333673K->249484K(349696K)] 355171K->249484K(502784K), [Metaspace: 2760K->2760K(1056768K)], 0.0326259 secs] [Times: user=0.31 sys=0.00, real=0.03 secs] 
..........中间省略部分............
---------------------第四部分------------------------------
Heap
 PSYoungGen      total 153088K, used 106759K [0x00000000f5580000, 0x0000000100000000, 0x0000000100000000)
  eden space 131584K, 81% used [0x00000000f5580000,0x00000000fbdc1ca0,0x00000000fd600000)
  from space 21504K, 0% used [0x00000000fd600000,0x00000000fd600000,0x00000000feb00000)
  to   space 21504K, 0% used [0x00000000feb00000,0x00000000feb00000,0x0000000100000000)
 ParOldGen       total 349696K, used 331587K [0x00000000e0000000, 0x00000000f5580000, 0x00000000f5580000)
  object space 349696K, 94% used [0x00000000e0000000,0x00000000f43d0fb8,0x00000000f5580000)
 Metaspace       used 2766K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 307K, capacity 386K, committed 512K, reserved 1048576K

内容：Minor GC + Full GC + Heap内存情况

第四部分：堆内存分布

• PSYoungGen total 75776K, used 63884K：年轻代占用75776K,，使用了63884K
  • eden space 65024K, 98% used，伊甸区占用了新生代65024K，其中98%被使用
  • from space 10752K, 0% used
  • to space 10752K, 0% used
• ParOldGen total 180736K, used 180448K，老年代总共180736K，使用了180448K
• Metaspace used 2766K, capacity 4486K, committed 4864K, reserved 1056768K：元数据区总计使用了2766K，容量是4486K，JVM保证可用的大小是4864K，保留空间1GB左右
  • class space used 307K, capacity 386K, committed 512K, reserved 1048576K，class space使用了307K，容量是386K

CMS GC

--------------------------第一部分----------------------------------
Java HotSpot(TM) 64-Bit Server VM (25.201-b09) for windows-amd64 JRE (1.8.0_201-b09), built on Dec 15 2018 18:36:39 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16657944k(2966240k free), swap 40559696k(11356008k free)
CommandLine flags: 
-XX:InitialHeapSize=536870912 
-XX:MaxHeapSize=536870912
-XX:MaxNewSize=178958336
-XX:MaxTenuringThreshold=6
-XX:NewSize=178958336 
-XX:OldPLABSize=16 
-XX:OldSize=357912576
-XX:+PrintGC
-XX:+PrintGCDateStamps
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+UseCompressedClassPointers
-XX:+UseCompressedOops
-XX:+UseConcMarkSweepGC
-XX:-UseLargePagesIndividualAllocation 
-XX:+UseParNewGC 
通过解析第一部分日志，我们可以看到，初始化堆内存大小与最大堆内存大小与并行GC是一样的，指定-XX:+UseConcMarkSweepGC默认会加上-XX:+UseParNewGC作为新生代GC
--------------------------第二部分MinorGC----------------------------------
2021-09-10T10:04:53.039+0800: 0.312: [GC (Allocation Failure) 2021-09-10T10:04:53.039+0800: 0.312: 
[ParNew: 157248K->17472K(157248K), 0.0148265 secs] 321753K->222842K(506816K), 0.0148801 secs] [Times: user=0.03 sys=0.03, real=0.01 secs] 
--------------------------第三部分Major GC----------------------------------
2021-09-10T10:04:53.054+0800: 0.327: [GC (CMS Initial Mark) [1 CMS-initial-mark: 205370K(349568K)] 223428K(506816K), 0.0001030 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T10:04:53.054+0800: 0.327: [CMS-concurrent-mark-start]
2021-09-10T10:04:53.057+0800: 0.330: [CMS-concurrent-mark: 0.003/0.003 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T10:04:53.057+0800: 0.330: [CMS-concurrent-preclean-start]
2021-09-10T10:04:53.058+0800: 0.331: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T10:04:53.058+0800: 0.331: [CMS-concurrent-abortable-preclean-start]
---------------------------中间穿插着MinorGC-----------------------------
2021-09-10T10:04:53.076+0800: 0.349: [GC (Allocation Failure) 2021-09-10T10:04:53.076+0800: 0.349: [ParNew: 157248K->17472K(157248K), 0.0156403 secs] 362618K->266214K(506816K), 0.0157138 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
2021-09-10T10:04:53.113+0800: 0.387: [GC (Allocation Failure) 2021-09-10T10:04:53.113+0800: 0.387: [ParNew: 157248K->17472K(157248K), 0.0155434 secs] 405990K->308435K(506816K), 0.0155941 secs] [Times: user=0.05 sys=0.02, real=0.02 secs] 
2021-09-10T10:04:53.149+0800: 0.423: [GC (Allocation Failure) 2021-09-10T10:04:53.149+0800: 0.423: [ParNew: 157074K->17472K(157248K), 0.0173170 secs] 448038K->353000K(506816K), 0.0173738 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
---------------------------中间穿插着MinorGC-----------------------------
2021-09-10T10:04:53.167+0800: 0.440: [CMS-concurrent-abortable-preclean: 0.003/0.109 secs] [Times: user=0.17 sys=0.02, real=0.11 secs] 
2021-09-10T10:04:53.167+0800: 0.440: [GC (CMS Final Remark) [YG occupancy: 20972 K (157248 K)]2021-09-10T10:04:53.167+0800: 0.440: [Rescan (parallel) , 0.0002117 secs]2021-09-10T10:04:53.167+0800: 0.440: [weak refs processing, 0.0000083 secs]2021-09-10T10:04:53.167+0800: 0.441: [class unloading, 0.0002509 secs]2021-09-10T10:04:53.168+0800: 0.441: [scrub symbol table, 0.0003192 secs]2021-09-10T10:04:53.168+0800: 0.441: [scrub string table, 0.0001136 secs][1 CMS-remark: 335528K(349568K)] 356500K(506816K), 0.0009630 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T10:04:53.168+0800: 0.441: [CMS-concurrent-sweep-start]
2021-09-10T10:04:53.169+0800: 0.442: [CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T10:04:53.169+0800: 0.442: [CMS-concurrent-reset-start]
2021-09-10T10:04:53.169+0800: 0.442: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

相较于上面的集中GC日志：

回收过程

这里多了一点 CMS 的Major GC的回收过程分析：（这里体现了更多回收细节）

• 初始化标记
• 并发标记
• 重新标记
• 并发清除

阶段1：初始标记
该阶段是STW的阶段，目的是标记所有的根对象包括根对象直接引用的对象，以及被年轻代中所有存活对象引用对象速度很快

2021-09-10T10:04:53.054+0800: 0.327:
[GC (CMS Initial Mark) 
 [1 CMS-initial-mark: 205370K(349568K)] 223428K(506816K), 0.0001030 secs] 
 [Times: user=0.00 sys=0.00, real=0.00 secs] 

• GC (CMS Initial Mark)—这个阶段的名称为“ Initial Mark”
• [1 CMS-initial-mark: 205370K(349568K)] 表示老年代的使用量以及老年代的大小
• 223428K(506816K), 0.0001030 secs–当前堆内存的使用量，以及可用的堆内存大小、GC消耗的时间，时间0.1毫秒，非常短，因为要标记的对象很少
• [Times: user=0.00 sys=0.00, real=0.00 secs] –初始标记暂停的时间，可以看到被忽略不计了

阶段2：并发标记
并发标记是从“初始标记”阶段编辑的根元素开始，标记所有存活的对象，GC线程与用户线程同时运行。

2021-09-10T10:04:53.054+0800: 0.327: [CMS-concurrent-mark-start]
2021-09-10T10:04:53.057+0800: 0.330: [CMS-concurrent-mark: 0.003/0.003 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

• CMS-concurrent-mark-start表明当前为CMS的并发标记阶段
• 0.003/0.003 secs-此阶段的持续时间，分别是GC线程消耗的时间和实际消耗的时间
• [Times: user=0.00 sys=0.00, real=0.00 secs]-对于并发阶段来说这些时间并没有多少意义，因为啥从并发标记时刻计算的，而这段时间应用程序也在执行，所以这个时间至少一个大概的值

阶段3：并发预清理
此阶段也是与用户线程同时运行的，主要是来出来“并发标记”阶段“脏卡”的老年代对象，为了减少Final Remark阶段STW的时间，可通过-XX:-CMSPrecleaningEnabled关闭，默认开启。

2021-09-10T10:04:53.057+0800: 0.330: [CMS-concurrent-preclean-start]
2021-09-10T10:04:53.058+0800: 0.331: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

与“并发标记”阶段相同
​

阶段4：可取消的并发预清理
具体此阶段的流程这里就不细讲了，目的与“并发预清理”一样，也是为了减少Final Remark阶段STW的时间，在进入Final Remark阶段前尽量等到一个Minor GC。具体的可以看我这篇CMS垃圾收集器。

2021-09-10T10:04:53.058+0800: 0.331: [CMS-concurrent-abortable-preclean-start]
==================================中间穿插着MinorGC================================
2021-09-10T10:04:53.076+0800: 0.349: [GC (Allocation Failure) 2021-09-10T10:04:53.076+0800: 0.349: [ParNew: 157248K->17472K(157248K), 0.0156403 secs] 362618K->266214K(506816K), 0.0157138 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
2021-09-10T10:04:53.113+0800: 0.387: [GC (Allocation Failure) 2021-09-10T10:04:53.113+0800: 0.387: [ParNew: 157248K->17472K(157248K), 0.0155434 secs] 405990K->308435K(506816K), 0.0155941 secs] [Times: user=0.05 sys=0.02, real=0.02 secs] 
2021-09-10T10:04:53.149+0800: 0.423: [GC (Allocation Failure) 2021-09-10T10:04:53.149+0800: 0.423: [ParNew: 157074K->17472K(157248K), 0.0173170 secs] 448038K->353000K(506816K), 0.0173738 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
==================================================================================
2021-09-10T10:04:53.167+0800: 0.440: [CMS-concurrent-abortable-preclean: 0.003/0.109 secs] [Times: user=0.17 sys=0.02, real=0.11 secs] 

可以看到预清理过程中，发生了三次Minor GC。
​

阶段5：最终标记
最终标记是CMS GC中的第二次STW，也是最后一次，该阶段重新扫描堆中的对象，因为之前的预清理阶段是并发执行的，有可能GC线程跟不上应用线程的修改速度，该阶段需要扫描新生代+GC Roots + 被标记为“脏区”的对象，如果预清理阶段没有做好，这一步扫描新生代会非常耗时

2021-09-10T10:04:53.167+0800: 0.440: [GC (CMS Final Remark) 
        [YG occupancy: 20972 K (157248 K)]2021-09-10T10:04:53.167+0800: 0.440: 
        [Rescan (parallel) , 0.0002117 secs]2021-09-10T10:04:53.167+0800: 0.440: 
        [weak refs processing, 0.0000083 secs]2021-09-10T10:04:53.167+0800: 0.441: 
        [class unloading, 0.0002509 secs]2021-09-10T10:04:53.168+0800: 0.441:
        [scrub symbol table, 0.0003192 secs]2021-09-10T10:04:53.168+0800: 0.441: 
        [scrub string table, 0.0001136 secs]
        [1 CMS-remark: 335528K(349568K)] 356500K(506816K), 0.0009630 secs] 
        [Times: user=0.00 sys=0.00, real=0.00 secs] 

• CMS Final Remark -阶段名称，最终标记阶段
• YG occupancy: 20972 K (157248 K) - 当前年轻代的使用量和总容量
• Rescan (parallel) , 0.0002117 secs - 在程序暂停后进行重新扫描，已完成存活对象的标记。并行执行，耗时0.0002117 secs
• weak refs processing, 0.0000083 secs - 第一个子阶段，处理弱引用，耗时0.0002117 secs
• class unloading, 0.0002509 secs - 第二个子阶段，卸载不使用的类，耗时0.0002509 secs
• scrub symbol table, 0.0003192 secs - 第三个子阶段，清理符号表，即持有class级别的metadata的符号表（symbol table）
• 1 CMS-remark: 335528K(349568K) - 此阶段完成后老年代的使用量和总容量
• 356500K(506816K), 0.0009630 secs - 此阶段完成整个堆内存的使用量和总容量，耗时

---

阶段6：并发清除
此阶段也是与用户线程同时运行的，删除不再使用的对象，并回收他们占用的内存空间，由于是与用户线程并发执行，因此可能会产生“浮动垃圾”

2021-09-10T10:04:53.168+0800: 0.441: [CMS-concurrent-sweep-start]
2021-09-10T10:04:53.169+0800: 0.442: [CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

与前边的阶段类似，不再讲解
​

阶段7：并发重置
此阶段也是与用户线程同时运行的，重置CMS算法相关的内部结构，下次触发GC时就可以直接使用

2021-09-10T10:04:53.169+0800: 0.442: [CMS-concurrent-reset-start]
2021-09-10T10:04:53.169+0800: 0.442: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

具体CMS GC后老年代内存使用量是多少这里并不能分析出来，只能通过后边的Minor GC日志分析，例如本次CMS GC后的Minor GC日志如下

2021-09-10T11:20:07.151+0800: 0.615: 
[GC (Allocation Failure) 2021-09-10T11:20:07.151+0800: 0.615: 
 [ParNew: 157248K->17472K(157248K), 0.0123639 secs] 446745K->354158K(506816K), 0.0124328 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 

计算出来老年代的使用率大约为83%，这个使用率并不度，说明了什么问题呢，一般就是分配的内存小了，毕竟我们才指定了512M最大堆内存

Full GC

当并发模式失败（Concurrent mod failure）会触发Full GC。

• 并发模式失败：CMS大部分阶段是与用户线程并发执行的，如果在执行垃圾收集时用户线程创建的对象直接往老年代分配，但是没有足够的内存，就会报Concurrent mode failure
• 晋升失败：新生代做Minor GC的时候，老年代没有足够的空间用来存放晋升的对象，则会报Concurrent mode failure；如果由于内存碎片问题导致无法分配，就会报晋升失败

可以看到下边的日志，先发生了一次concurrent mode failure，后边紧接着发生了一次Full GC

java
复制代码CMS2021-09-10T22:33:50.168+0800: 0.562: [CMS-concurrent-abortable-preclean: 0.000/0.017 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
 (concurrent mode failure): 331593K->349531K(349568K), 0.0564298 secs] 471258K->361742K(506816K), [Metaspace: 2760K->2760K(1056768K)], 0.0566131 secs] [Times: user=0.05 sys=0.00, real=0.06 secs] 
 
2021-09-10T22:33:50.246+0800: 0.640: [Full GC (Allocation Failure) 2021-09-10T22:33:50.246+0800: 0.640: [CMS: 349531K->349151K(349568K), 0.0528130 secs] 506497K->392533K(506816K), [Metaspace: 2760K->2760K(1056768K)], 0.0529324 secs] [Times: user=0.05 sys=0.00, real=0.05 secs] 

G1 GC

Java HotSpot(TM) 64-Bit Server VM (25.201-b09) for windows-amd64 JRE (1.8.0_201-b09), built on Dec 15 2018 18:36:39 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16657944k(1124124k free), swap 40559696k(8067960k free)
CommandLine flags: 
-XX:InitialHeapSize=536870912 
-XX:MaxHeapSize=536870912
-XX:+PrintGC
-XX:+PrintGCDateStamps
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:-UseAdaptiveSizePolicy
-XX:+UseCompressedClassPointers
-XX:+UseCompressedOops
-XX:+UseG1GC
-XX:-UseLargePagesIndividualAllocation 

2021-09-10T14:31:56.590+0800: 0.429: [GC pause (G1 Evacuation Pause) (young), 0.0122670 secs]
   [Parallel Time: 2.6 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 437.9, Avg: 437.9, Max: 438.0, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.2, Avg: 0.8, Max: 2.5, Diff: 2.3, Sum: 3.1]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.0, Avg: 1.6, Max: 2.3, Diff: 2.3, Sum: 6.5]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 0.6]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 2.5, Avg: 2.6, Max: 2.6, Diff: 0.1, Sum: 10.4]
      [GC Worker End (ms): Min: 440.5, Avg: 440.5, Max: 440.5, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 9.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 25.0M(25.0M)->0.0B(21.0M) Survivors: 0.0B->4096.0K Heap: 31.2M(512.0M)->13.9M(512.0M)]
 [Times: user=0.00 sys=0.00, real=0.01 secs] 
 
----------------------------------------------------------------------
    2021-09-10T14:31:57.007+0800: 0.846: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0130786 secs]
   [Parallel Time: 12.8 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 845.8, Avg: 845.9, Max: 846.0, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.4]
      [Update RS (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.6]
         [Processed Buffers: Min: 2, Avg: 2.8, Max: 3, Diff: 1, Sum: 11]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 11.8, Avg: 12.0, Max: 12.4, Diff: 0.6, Sum: 47.8]
      [Termination (ms): Min: 0.0, Avg: 0.4, Max: 0.6, Diff: 0.6, Sum: 1.7]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 12.6, Avg: 12.7, Max: 12.8, Diff: 0.2, Sum: 50.6]
      [GC Worker End (ms): Min: 858.5, Avg: 858.6, Max: 858.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 0.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 118.0M(123.0M)->0.0B(161.0M) Survivors: 12.0M->17.0M Heap: 321.1M(512.0M)->221.0M(512.0M)]
 [Times: user=0.00 sys=0.06, real=0.01 secs] 


------------------------------------------------------------------
2021-09-10T14:31:57.020+0800: 0.859: [GC concurrent-root-region-scan-start]
2021-09-10T14:31:57.020+0800: 0.859: [GC concurrent-root-region-scan-end, 0.0001075 secs]
2021-09-10T14:31:57.020+0800: 0.859: [GC concurrent-mark-start]
2021-09-10T14:31:57.023+0800: 0.861: [GC concurrent-mark-end, 0.0023080 secs]
2021-09-10T14:31:57.023+0800: 0.862: [GC remark 2021-09-10T14:31:57.023+0800: 0.862: [Finalize Marking, 0.0000914 secs] 2021-09-10T14:31:57.023+0800: 0.862: [GC ref-proc, 0.0000388 secs] 2021-09-10T14:31:57.023+0800: 0.862: [Unloading, 0.0003763 secs], 0.0008956 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T14:31:57.024+0800: 0.863: [GC cleanup 232M->230M(512M), 0.0002672 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T14:31:57.024+0800: 0.863: [GC concurrent-cleanup-start]
2021-09-10T14:31:57.024+0800: 0.863: [GC concurrent-cleanup-end, 0.0000103 secs]
---------------------------------------------------------------------
2021-09-10T14:31:57.063+0800: 0.902: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0028671 secs]
   [Parallel Time: 2.1 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 902.0, Avg: 902.2, Max: 902.4, Diff: 0.4]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.4]
      [Update RS (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 0.8]
         [Processed Buffers: Min: 2, Avg: 4.0, Max: 8, Diff: 6, Sum: 16]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 1.6, Avg: 1.6, Max: 1.6, Diff: 0.0, Sum: 6.3]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 1.7, Avg: 1.9, Max: 2.1, Diff: 0.4, Sum: 7.5]
      [GC Worker End (ms): Min: 904.1, Avg: 904.1, Max: 904.1, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 0.7 ms]
      [Evacuation Failure: 0.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.0 ms]
   [Eden: 161.0M(161.0M)->0.0B(13.0M) Survivors: 17.0M->12.0M Heap: 439.1M(512.0M)->371.4M(512.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
 
---------------------------------------------------------------------
    2021-09-10T14:31:57.069+0800: 0.908: [GC pause (G1 Evacuation Pause) (mixed), 0.0045144 secs]
   [Parallel Time: 4.2 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 908.2, Avg: 908.2, Max: 908.2, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.6]
      [Update RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.8]
         [Processed Buffers: Min: 2, Avg: 3.8, Max: 5, Diff: 3, Sum: 15]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 3.7, Avg: 3.8, Max: 3.8, Diff: 0.1, Sum: 15.0]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 4.2, Avg: 4.2, Max: 4.2, Diff: 0.0, Sum: 16.8]
      [GC Worker End (ms): Min: 912.3, Avg: 912.4, Max: 912.4, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 0.2 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 13.0M(13.0M)->0.0B(48.0M) Survivors: 12.0M->4096.0K Heap: 389.0M(512.0M)->353.1M(512.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
--------------------------------------------------------------------

Heap
 garbage-first heap   total 524288K, used 385426K [0x00000000e0000000, 0x00000000e0101000, 0x0000000100000000)
  region size 1024K, 4 young (4096K), 2 survivors (2048K)
 Metaspace       used 2614K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 288K, capacity 386K, committed 512K, reserved 1048576K

JVM 调优

性能指标

-★ 响应时间（Response Time: RT）

响应时间指用户从客户端发起一个请求开始，到客户端接收到从服务器端返回的响
应结束，整个过程所耗费的时间。
HPS（Hits Per Second） ：每秒点击次数，单位是次/秒。
★TPS（Transaction per Second）：系统每秒处理交易数，单位是笔/秒。
★QPS（Query per Second）：系统每秒处理查询次数，单位是次/秒。

对于互联网业务中，如果某些业务有且仅有一个请求连接，那么 TPS=QPS=HPS，一
般情况下用 TPS 来衡量整个业务流程，用 QPS 来衡量接口查询次数，用 HPS 来表
示对服务器单击请求。

无论 TPS、QPS、HPS,此指标是衡量系统处理能力非常重要的指标，越大越好，根据经
验，一般情况下：
金融行业：1000TPS50000TPS，不包括互联网化的活动（秒杀等）
保险行业：100TPS100000TPS，不包括互联网化的活动
制造行业：10TPS5000TPS
互联网电子商务：10000TPS1000000TPS
互联网中型网站：1000TPS50000TPS
互联网小型网站：500TPS10000TPS
最大响应时间（Max Response Time） 指用户发出请求或者指令到系统做出反应（响应）
的最大时间。
最少响应时间（Mininum ResponseTime） 指用户发出请求或者指令到系统做出反应（响
应）的最少时间。
90%响应时间（90% Response Time） 是指所有用户的响应时间进行排序，第 90%的响应时间。
从外部看，性能测试主要关注如下三个指标
吞吐量可以理解为TPS或QPS：每秒钟系统能够处理的请求数、任务数。
响应时间：服务处理一个请求或一个任务的耗时。
错误率：一批请求中结果出错的请求所占比例。

(13条消息) ＜JVM下篇：性能监控与调优篇＞03-JVM监控及诊断工具-GUI篇_VectorUx的博客-CSDN博客

压力测试

谷粒商城分布式高级（五）—— 性能压测（压力测试 & 性能监控 & nginx动静分离 ） - 沧海一粟hr - 博客园 (cnblogs.com)

火焰图

火焰图实践 - 知乎 (zhihu.com)

1. 场景描述：

因为生产环境组件服务进程执行缓慢导致部分资源无法释放，进而引起了各种任务超时。研究源码发现，部分执行过长的是操作都是在单线程中串行 。这就意味着，单个过程的执行效率会影响到整个流程的调度周期。为此，我们需要对部分组件源码进行改造，串行改并行。
串行改并行，我们要小心流程执行顺序之间的依赖关系和各个线程对共享变量的读写。这里的前提是我们得知道改哪里。其实我们的需求很明确，执行过程耗时长的我们优先改造,也就是我们需要找到组件的性能瓶颈。但是如何确认呢?最终，我是通过火焰图观察，找出了耗时比较长的过程。下面记录一下这个过程，以便日后需要的时候可以有所帮助。

2. 火焰图

火焰图是通过可交互的图片反映出程序执行过程中的调用栈和大致的CPU占用百分比。在火焰图中，顺着Y轴从下往上看表示的是调用顺序，高度表示的就是调用栈的深度。顺着X轴看，一个方法的长度表示的就是这个方法的被抽到的样本数，被抽到的次数越多，占用的CPU时间就越长。当把鼠标放在一个方法上时，会显示一段说明，例如(5222 samples, 7.6%),这个表示的就是，这个方法在采样期间被采样了5222次，占用总样本的7.6%。注意X轴不表示时间，不是说左边的方法一定在右边之前执行。火焰图应该是高低起伏的，如果都是很宽的平顶，那程序性能就需要重新评测了。另外，火焰图的颜色没有任何含义。

火焰图是可交互的，在浏览器中我们打开火焰图之后可以直接CTRL+F进行搜索。输入完整的方法名或者正则表达式之后，所有匹配到的方法都是高亮显示出来。

单击这些高亮部分就会放大这一部分，显示选中方法的子方法(被调用的方法)。这样就可以在这张图中搜索自己想要确认的模块，然后找到比较宽的部分，定位到代码，确定是否可以修改。

3. 生成火焰图

3.1 工具

火焰图生成工具：javaPfro.zip 提取码：76o9
这个工具包解压之后会用两个文件夹：
async-profiler-master FlameGraph-master
文件夹下部分可执行文件，可能需要755权限。这里不做一一声明，直接更改文件夹下所有文件的权限。
chmod -R 755 async-profiler-master/*
chmod -R 755 FlameGraph-master/*

3.2 操作步骤

火焰图只是以图片形式展示出了CPU中的调用栈，实际的数据还是需要从CPU中采集。所以生成火焰图共分为两步：采样和生成svg图。

3.2.1 采样

采样使用async-profiler-master工具，具体命令如下：
./async-profiler-master/profiler.sh -d 10 -o collapsed -f /tmp/collapsed.txt 1234
以上命令表示的意思是，采样时间为10秒，采样得到的数据重定向到/tmp/collapsed.txt，被采样进程id为1234。

3.2.2 生成svg图

根据采样数据生成svg图，使用的是FlameGraph-master,具体命令如下:
./FlameGraph-master/flamegraph.pl --colors=java /tmp/collapsed.txt > flamegraph.svg
命令表示的意思是把/tmp/collapsed.txt这个文件转换svg火焰图，文件名为flamegraph.svg。
然后,把这个文件拉到window环境下，用浏览器就可以打开了。这里我用的是chrome浏览器。

4. 分析火焰图

分析火焰图一般需要先确定需要分析的类或方法名，或者代码入口方法，或者入口类。这样我们可以先定位到一个方法调用，再分析其调用栈。

例如，在这张图片中，我确定的方法是定义在CoordinatorRunnable类中的，就可以直接搜索这个类。定位到这个类我们可以明显地看到有三个方法占用了大部分的时间。再继续追踪调用栈。

可以看出，耗时大部分都花费在集合元素的比较上。这里我们如果需要优化的话，可以考虑一下比较器的逻辑或者可以根据场景判断一下是否可以选择其他的集合等等。火焰图实践