在定位线上问题时，经常需要对JVM内存情况进行分析。在java类加载器问题思考与简单模拟热部署 中为了查看类代理生成情况，介绍了图形化工具HSDB的使用，而生产上进行分析更多的是使用jmap、jstat等工具，在java 8又提供了jcmd这一新的升级版工具；查看gc日志可以了解到详细的GC信息；linux提供了GDB、trace、perf等调试利器
然而，jmap等工具有着一些难以克服的问题：需要JVM pause导致服务暂停；开发人员需要登录服务器操作（虽然可以连接远程server，但也需要开放网络端口）；修改代码、测试需要重新打包发布。Arthas 是阿里开源的线上监控诊断产品，克服了这些缺点，支持在线解决生产问题，无需JVM重启，无需代码更改，不会暂停正在运行的线程
不得不提的是，不管是jmap、jstat，又或者arthas，在生产环境直接使用都是有风险的。内存的dump、线程堆栈的获取，不得不暂停JVM，即使这个过程很快，也难以完全避免服务中断；部分操作可能引起JVM崩溃，影响稳定性；等等。如何线上排查？首先的大原则是，解决问题优先于定位原因，只有在解决问题且有条件的情况下才应该扎进去定位原因；然后，根据部署情况评估是否要切走问题进程的流量后再进行排查；保护现场，尽可能留存日志、线程堆栈、内存dump等信息；想办法复现验证
以下的示例都在java 8进行
jmap的使用 jmap最常用的功能是参看JVM堆内存情况和导出JVM的内存dump
测试的java进程启动时使用的参数为”-Xms512m -Xmx512m -XX:+UseConcMarkSweepGC -XX:+CMSIncrementalMode”，其他使用默认参数；默认NewRatio=2，我们可以算出，老年代最大为512/(1+2)*2约341MB，年轻代则为约170MB；而默认的SurvivorRatio=8，因此Eden区最大约为136MB，两个Survivor区最大约为17MB
attach到JVM进程并输出堆内存情况（也可以指定分析一个dump文件）
输出类似：
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 Attaching to process ID 3629, please wait... Debugger attached successfully. Server compiler detected. JVM version is 25.351-b10 using parallel threads in the new generation. using thread-local object allocation. Concurrent Mark-Sweep GC Heap Configuration: MinHeapFreeRatio = 40 MaxHeapFreeRatio = 70 MaxHeapSize = 536870912 (512.0MB) NewSize = 178913280 (170.625MB) MaxNewSize = 178913280 (170.625MB) OldSize = 357957632 (341.375MB) NewRatio = 2 SurvivorRatio = 8 MetaspaceSize = 21807104 (20.796875MB) CompressedClassSpaceSize = 1073741824 (1024.0MB) MaxMetaspaceSize = 17592186044415 MB G1HeapRegionSize = 0 (0.0MB) Heap Usage: New Generation (Eden + 1 Survivor Space): capacity = 161021952 (153.5625MB) used = 85698208 (81.72817993164062MB) free = 75323744 (71.83432006835938MB) 53.22144399292837% used Eden Space: capacity = 143130624 (136.5MB) used = 85230712 (81.28234100341797MB) free = 57899912 (55.21765899658203MB) 59.54750256660657% used From Space: capacity = 17891328 (17.0625MB) used = 467496 (0.44583892822265625MB) free = 17423832 (16.616661071777344MB) 2.6129754035027473% used To Space: capacity = 17891328 (17.0625MB) used = 0 (0.0MB) free = 17891328 (17.0625MB) 0.0% used concurrent mark-sweep generation: capacity = 357957632 (341.375MB) used = 53575856 (51.09391784667969MB) free = 304381776 (290.2810821533203MB) 14.967094206277462% used
从输出中可以理解到JVM使用的GC算法、各个区域的大小和使用情况
可以使用以下命令attach到一个JVM进程并dump内存到指定文件core.dump
1 jmap -dump:format=b,file=core.dump <pid>
如果无响应，可以指定-F强制导出；导出的dump文件可以使用jhat、jprofiler等工具进行分析。dump也可以指定:live参数只输出活对象
使用histo参数可以attach到JVM进程（也可以指定dump文件），查看每个class的实例数、占用情况，使用:live可以指定只查看存活的对象
输出包括实例数、大小和类名，类似：
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 num #instances #bytes class name ---------------------------------------------- 1: 126683 11803240 [C 2: 35038 3083344 java.lang.reflect.Method 3: 126242 3029808 java.lang.String 4: 71742 2295744 java.util.concurrent.ConcurrentHashMap$Node 5: 38433 2149048 [Ljava.lang.Object; 6: 9809 1950192 [B 7: 17211 1927080 java.lang.Class 8: 8684 1588624 [I 9: 32634 1305360 java.util.LinkedHashMap$Entry 10: 12941 1056896 [Ljava.util.HashMap$Node; 11: 26644 852608 java.util.HashMap$Node 12: 13122 734832 java.util.LinkedHashMap 13: 29041 696984 java.util.ArrayList 14: 38200 611200 java.lang.Object 15: 512 571152 [Ljava.util.concurrent.ConcurrentHashMap$Node; 16: 21041 472888 [Ljava.lang.Class; 17: 7932 380736 java.util.HashMap
histo参数导出的信息可以让我们了解到heap的使用情况分布；间隔一段时间多次导出histo的信息进行对比，还可以观察到对象实例分配的变化情况
使用clstats参数可以查看方法区相关的类加载器的统计信息：
输出类似：
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 class_loader classes bytes parent_loader alive? type <bootstrap> 3519 6119418 null live <internal> 0x00000000ecd144d0 1 880 0x00000000eaaa0000 dead sun/reflect/DelegatingClassLoader@0x0000000100009e78 0x00000000ed591958 1 1473 0x00000000eaaa0000 dead sun/reflect/DelegatingClassLoader@0x0000000100009e78 0x00000000eb02df00 1 1471 0x00000000eaaa0000 dead sun/reflect/DelegatingClassLoader@0x0000000100009e78 0x00000000ecb28cb0 1 1474 null dead sun/reflect/DelegatingClassLoader@0x0000000100009e78 0x00000000ed56e150 1 880 0x00000000eaaa0000 dead sun/reflect/DelegatingClassLoader@0x0000000100009e78 0x00000000ed07e100 1 1475 0x00000000eaaa0000 dead sun/reflect/DelegatingClassLoader@0x0000000100009e78 0x00000000ecd154d8 1 880 0x00000000eaaa0000 dead sun/reflect/DelegatingClassLoader@0x0000000100009e78 0x00000000ecb29cb8 1 882 0x00000000eaaa0000 dead sun/reflect/DelegatingClassLoader@0x0000000100009e78 0x00000000ed1a6d10 1 1473 0x00000000eaaa0000 dead sun/reflect/DelegatingClassLoader@0x0000000100009e78 0x00000000ed224928 1 880 0x00000000eaaa0000 dead sun/reflect/DelegatingClassLoader@0x0000000100009e78 0x00000000ed520558 1 880 0x00000000eaaa0000 dead sun/reflect/DelegatingClassLoader@0x0000000100009e78 0x00000000ed567958 1 880 0x00000000eaaa0000 dead sun/reflect/DelegatingClassLoader@0x0000000100009e78 0x00000000ed56bd58 1 1473 0x00000000eaaa0000 dead sun/reflect/DelegatingClassLoader@0x0000000100009e78 0x00000000ecc740c8 1 880 null dead sun/reflect/DelegatingClassLoader@0x0000000100009e78
输出包括类加载器、加载类的数量、类元数据大小、父加载器、存活状态等
另，为java进程添加以下参数可以在JVM出现OOM崩溃时自动生成dump文件：
1 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=./dump.hprof
jstat的使用 jstat用于查看堆内存及GC信息，支持的参数较多，可以参考网友的总结
最常用的是-gc和-gcutil参数
-gc将输出堆内存各个区域的使用量和最大容量，以及YoungGC、FullGC次数及耗时
1 jstat -gc <pid> <interval> <count>
例如一下参数将每500ms输出一次、共输出5次
输出类似：
1 2 3 4 5 6 S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT 17472.0 17472.0 0.0 566.0 139776.0 26040.1 349568.0 45522.1 101792.0 94752.5 12224.0 11003.1 143 0.734 9 0.594 1.328 17472.0 17472.0 0.0 566.0 139776.0 26040.1 349568.0 45522.1 101792.0 94752.5 12224.0 11003.1 143 0.734 9 0.594 1.328 17472.0 17472.0 0.0 566.0 139776.0 26040.1 349568.0 45522.1 101792.0 94752.5 12224.0 11003.1 143 0.734 9 0.594 1.328 17472.0 17472.0 0.0 566.0 139776.0 26040.1 349568.0 45522.1 101792.0 94752.5 12224.0 11003.1 143 0.734 9 0.594 1.328 17472.0 17472.0 0.0 566.0 139776.0 26040.1 349568.0 45522.1 101792.0 94752.5 12224.0 11003.1 143 0.734 9 0.594 1.328
输出的列中，后缀为U代表Used使用量（KB），C代表Capacity最大容量（KB）；S0表示Survivor 0区域，同理S1表示Survivor 1区域；E表示Eden区；O表示Old区即老年代；M表示Meta区即方法区（元数据区）；CCS表示Compressed Class Space即压缩类空间（class指针压缩相关）；YGC表示YoungGC次数，YCGT表示YoundGC耗时（秒），FGC、FGCT及GCT同理
-gcutil的作用与-gc类似，不过输出的是百分比而不是使用量：
1 jstat -gcutil <pid> 500 5
输出类似：
1 2 3 4 S0 S1 E O M CCS YGC YGCT FGC FGCT GCT 0.00 3.24 50.83 13.02 93.08 90.01 143 0.734 9 0.594 1.328 0.00 3.24 50.83 13.02 93.08 90.01 143 0.734 9 0.594 1.328 0.00 3.24 50.83 13.02 93.08 90.01 143 0.734 9 0.594 1.328
通过对比多条输出中各区域的变化情况及GC次数，可以猜测GC问题所在
GC日志分析 关于GC log的分析，主要学习自这篇文章 ，结合了一部分个人经历
在java 8中使用一下参数开启GC日志输出：
1 -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:./logs/gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=8 -XX:GCLogFileSize=8m
其中，-Xloggc指定gc log文件位置，UseGCLogFileRotation、NumberOfGCLogFiles、GCLogFileSize用于配置日志滚动
使用一下参数启动java测试进程：
1 java -Xms200m -Xmx200m -Xmn100m -XX:+UseConcMarkSweepGC -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:./gc.log -jar xxx.jar
gc log如：
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 2024-06-06T20:39:22.711+0800: 1.227: [GC (Allocation Failure) 2024-06-06T20:39:22.711+0800: 1.228: [ParNew: 81920K->9789K(92160K), 0.0200098 secs] 81920K->28238K(194560K), 0.0205668 secs] [Times: user=0.03 sys=0.05, real=0.02 secs] 2024-06-06T20:39:23.011+0800: 1.527: [Full GC (Allocation Failure) 2024-06-06T20:39:23.011+0800: 1.527: [CMS: 101869K->101867K(102400K), 0.0085520 secs] 192034K->186908K(194560K), [Metaspace: 4052K->4052K(1056768K) ], 0.0086524 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 2024-06-06T20:39:22.793+0800: 1.310: [GC (CMS Initial Mark) [1 CMS-initial-mark: 88612K(102400K)] 100973K(194560K), 0.0013844 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2024-06-06T20:39:22.795+0800: 1.311: [CMS-concurrent-mark-start] 2024-06-06T20:39:22.796+0800: 1.312: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2024-06-06T20:39:22.796+0800: 1.312: [CMS-concurrent-preclean-start] 2024-06-06T20:39:22.796+0800: 1.313: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2024-06-06T20:39:22.796+0800: 1.313: [CMS-concurrent-abortable-preclean-start] 2024-06-06T20:39:22.796+0800: 1.313: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2024-06-06T20:39:22.797+0800: 1.313: [GC (CMS Final Remark) [YG occupancy: 19865 K (92160 K)]2024-06-06T20:39:22.797+0800: 1.313: [Rescan (parallel) , 0.0003616 secs]2024-06-06T20:39:22.797+0800: 1.313: [weak refs processing, 0.0000255 secs]2024-06-06T20:39:22.797+0800: 1.313: [class unloading, 0.0005809 secs]2024-06-06T20:39:22.798+0800: 1.314: [scrub symbol table, 0.0002738 secs]2024-06-06T20:39:22.798+0800: 1.314: [scrub string table, 0.0000782 secs][1 CMS-remark: 88612K(102400K)] 108478K(194560K), 0.0013943 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2024-06-06T20:39:22.798+0800: 1.315: [CMS-concurrent-sweep-start] 2024-06-06T20:39:22.798+0800: 1.315: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2024-06-06T20:39:22.798+0800: 1.315: [CMS-concurrent-reset-start] 2024-06-06T20:39:22.799+0800: 1.316: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
每条日志主要包含以下部分：GC发生时间；GC类型-GC原因；各区域GC收集器类型-GC区域回收情况；堆GC回收情况；GC耗时
GC类型包括GC（指Young GC）和Full GC
GC原因较多，主要的有：
Allocation Failure，表示因对象分配失败而发生GC——其实一般来说，除非是测试代码中特意制造的场景，大多不会出现在Full GC，如果出现则意味着存在巨大的问题（内存泄漏？大对象？堆内存配置很小？）
CMS，CMS的详细过程，根据其原理，重点需要关注的是CMS Initial Mark和CMS Final Remark两个阶段——这两个阶段是需要STW的
Promotion Failure，年轻代存活对象晋升老年代时没有足够空间引起的GC
METADATA GC THREADHOLD，方法区内存不足引起。默认方法区空间是自动调整、自动扩展的，可以通过MaxMetaSpaceSize限制其扩展上限。如果出现了此类GC，关键的问题就是classloader不断加载class，基本是动态加载类引起的
System，手动调用System.gc()引起的GC操作
各区域GC收集器类型，除了老年代最常用的CMS，常见的还有：
DefNew，表示Default New Generation，指年轻代使用的Serial收集器
ParNew，表示Parallel New Generation，指年轻代使用的ParNew收集器
PSYoungGen，指年轻代使用的Parallel Scavenage
ParOldGen，指老年代使用的Parallel Old收集器
garbage-fisrt heap，使用G1收集器时出现
以此为例：
1 2024-06-06T20:39:22.711+0800: 1.227: [GC (Allocation Failure) 2024-06-06T20:39:22.711+0800: 1.228: [ParNew: 81920K->9789K(92160K), 0.0200098 secs] 81920K->28238K(194560K), 0.0205668 secs] [Times: user=0.03 sys=0.05, real=0.02 secs]
GC回收情况，类似：[ParNew: 81920K->9789K(92160K), 0.0200098 secs]，分别表示：[年轻代、ParNew收集器: 使用回收前内存占用->回收后内存占用(此内存区域最大容量), GC耗时]
而：81920K->28238K(194560K), 0.0205668 secs，表示：回收前堆内存占用->回收后堆内存占用(堆最大容量)（当然，这里的堆最大容量194560K = 190M，而指定的Xmx为200M，这里和jmap/jstat的输出一样，是统计口径的问题，from/to区只会使用到一个，因此堆最大可用空间为200-10=190M）；类似的，Metaspace的GC情况同理
结合年轻代回收量和堆整体回收量来看，这次回收中年轻代回收了81920K-9789K = 72031K，堆整体占用减少了81920K-28238K = 53682K，这说明年轻代有72031K-53682K = 18349K晋升到了老年代
GC耗时，如上例的：[Times: user=0.03 sys=0.05, real=0.02 secs]，user-用户态耗时，sys-内核态耗时，real-这次GC中客观世界经历的时长
如何理解real？举个例子，假如GC使用2个线程同一时刻开始并行执行回收，分别使用了0.1s和0.2s完成，那么user+sys为0.3s，但是real为0.2s
常见GC问题 一个曾遇到的情况：gc log显示，full gc频繁，并且full gc过程回收的空间比较大。这是很不合理的情况，老年代本身定位于存储存活时间长的对象，那为何一次gc会会收大量对象呢？我们知道，年轻代对象除了经过多次GC存活后晋升到老年代之外，如果年轻代容量不足，会有老年代提供分配担保，将不足以容纳的对象移入老年代；所以，出现这种情况，可以尝试增大年轻代空间。多大合适？full gc后老年代存活对象占用空间可以认为是老年代活跃对象的占用空间，一个经验值，将老年代容量设置为活跃对象占用的3倍为宜；除此之外的空间，可以全部给到年轻代
GC real很高？ 有些情况下，我们会遇到一种情况：GC log显示的sys、user耗时都很短，但是real却很高
普通的业务应用可能比较少遇到这种情况，但是在大数据等场景下，相信做过排查的朋友一定有印象。典型的一个原因就是，服务器IO负载极高，导致GC log写出到磁盘耗时显著增加（是的，写gc log不是异步的，至少在jdk8的版本中不是），即阻塞时间增加，导致real time很高。这种情况在一般的业务系统相信很难出现，也很难通过模拟的方式来产生这种级别的IO负载；在大数据场景下，极重的shuffle等IO密集场景+flink实时任务等高敏感任务，会成为大问题
使用GDB分析JVM内存 堆内存出现问题，分析gc、分析dump文件等，容易操作。但是堆外内存出现问题时，排查的复杂性就大大高了
遇到过一个现象：java进程在操作系统的内存占用中，RSS远远超出了堆内存Xmx，此时往往意味着问题在于堆外内存。
这种情况下，java 8引入的jcmd工具可以使用-XX:NativeMemoryTracking=detail参数查看Native memory的情况，可以一定程度上帮助排查
linux的gdb、pmap工具，可以对进程的内存进行dump，分析可疑的内存块；strace工具可以设置追踪内存分配相关的调用进行观察。
这类工具并不适合用于日常性普通问题的排查——换言之，需要用上这类工具，都是极其复杂、深入的问题，没有对OS、JVM足够的了解，没有足够的经验支撑，是很难进行的
Arthas的使用 arthas的安装和启动参考官方文档。这里对使用arthas内存相关的命令简单演示
启动arthas后attach到java进程，使用dashboard命令查看JVM基本的线程、内存、运行环境等信息：
输出类似：
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 ID NAME GROUP PRIORI STATE %CPU DELTA_ TIME INTER DAEMON 54 System Clock main 5 TIMED_ 0.0 0.000 224:36 false true -1 VM Periodic Task Th - -1 - 0.0 0.000 8:26.3 false true 19 lettuce-timer-3-1 main 5 TIMED_ 0.0 0.000 3:44.8 false true 17 Catalina-utility-2 main 1 TIMED_ 0.0 0.000 0:45.0 false false 16 Catalina-utility-1 main 1 WAITIN 0.0 0.000 0:44.1 false false -1 C2 CompilerThread1 - -1 - 0.0 0.000 0:36.2 false true 35 http-nio-8090-Polle main 5 RUNNAB 0.0 0.000 0:32.5 false true -1 C2 CompilerThread0 - -1 - 0.0 0.000 0:31.8 false true -1 VM Thread - -1 - 0.0 0.000 0:23.2 false true 43 mysql-cj-abandoned- main 5 TIMED_ 0.0 0.000 0:17.4 false true Memory used total max usage GC heap 153M 494M 494M gc.parnew.count 348 par_eden_space 86M 136M 136M gc.parnew.time(ms) 1237 par_survivor_spa 17M 17M 17M 100.0 gc.concurrentmarksw 5 ce 0% eep.count cms_old_gen 50M 341M 341M gc.concurrentmarksw 594 nonheap 176M 185M -1 eep.time(ms) code_cache 58M 58M 240M Runtime os.name Linux os.version 3.10.0-1160.90.1.el7.x86_64 java.version 1.8.0_351
使用memory命令可以查看内存信息：
输出与dashboard中内存信息一致：
1 2 3 4 5 6 7 8 9 10 11 Memory used total max usage heap 167M 494M 494M 33.86% par_eden_space 100M 136M 136M 73.51% par_survivor_space 17M 17M 17M 100.00% cms_old_gen 50M 341M 341M 14.69% nonheap 176M 186M -1 94.94% code_cache 58M 58M 240M 24.29% metaspace 106M 113M -1 93.41% compressed_class_space 12M 13M 1024M 1.19% direct 80K 80K - 100.00% mapped 0K 0K - 0.00%
其中：
heap，堆内存
par_eden_space，eden区，这里年轻代使用的是ParNew收集器
par_survivor_space，form/to区
cms_old_gen，老年代，这里使用的cms收集器
nonheap，非堆内存（栈、方法区等）
code_cache，JIT使用的代码缓存区域
metaspace，方法区
compressed_class_space，压缩类空间
direct，堆外direct直接内存（JNI、ByteBuffer等使用）
mapped，堆外Mapped memory(使用mmap)
可以观察到，nonheap 约等于 code_cache + metaspace + compressed_class_space + direct + mapped ——对照arthas源代码 ，这里的nonheap与之后几项也的确是总-分关系
使用heapdump可以dump内存到文件
1 2 3 heapdump # 使用--live指定只导出存活对象 heapdump --live
1 2 Dumping heap to /tmp/heapdump2024-06-13-21-20566951954109687382.hprof ... Heap dump file created
arthas的功能远比以上示例多得多，实际上，相比于查看JVM运行状态，可能对类、方法的调用调试功能更为有用