跳至主要內容

JVM (十四) visualVM 使用分析 GC 日志/OOM

安图新大约 22 分钟

JVM (十四) visualVM 使用分析 GC 日志/OOM

1:关于 visualVM 的使用介绍

参见:https://www.cnblogs.com/krock/p/14419459.html

2:测试

环境:jdk1.8, window

1)Metaspace OOM

测试代码:

   

public static void main(String[]args) {
        while (true) {
            try {
                Thread.sleep(10);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            Enhancer enhancer = new Enhancer();
            enhancer.setSuperclass(MytestwebApplicationTests.class);
            enhancer.setUseCache(false);
            enhancer.setCallback(new MethodInterceptor() {
                public Object intercept(Object obj, Method method, Object[] args, MethodProxy proxy) throws Throwable {
                    return proxy.invokeSuper(obj, args);
                }
            });
            long initialHeapSize = Runtime.getRuntime().totalMemory();
            long maxHeapSize = Runtime.getRuntime().maxMemory();
            /*System.out.println("-Xms = " + initialHeapSize / 1024 + "kb or " + initialHeapSize / 1024 / 1024 + "mb");
            System.out.println("-Xmx = " + maxHeapSize / 1024 + "kb or " + maxHeapSize / 1024 / 1024 + "mb");
*/           System.out.println("running...");

            enhancer.create();
        }
    }

元空间 OOM 测试代码

JVM 参数:JVM 基本参数介绍参见: https://www.cnblogs.com/krock/p/14417036.html

   

-Xms256m
-Xmx256m
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:MetaspaceSize=68m
-XX:MaxMetaspaceSize=68m
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=D:\indigoProject\LinkScape\testFolder\guobao\sourceFile
-Xloggc:D:\indigoProject\LinkScape\testFolder\guobao\sourceFile\gc.log

JVM 参数

 
 

运行这个程序之后,在 visualVM 中会自动捕获到这个线程,打开之后由于堆设置的很小,已经开始频繁发生 Minor GC(新生代 GC)了,博客无法上传视频,我截图两个不同时刻的图片看下,如果自己测试的话就可以明显看到,Eden 反复从满到空闲,S0 和 S1 反复切换 From,To 角色,Metaspace 里面装载的类逐渐增加。

时刻 1:

 
 

时刻 2:

 
 

最后程序停止之后的图形:

 
 
 
 

执行一段时间 Metaspace 就报了内存不足的错误:
 

2)分析 GC 日志

去把 GC 日志打开看:完整日志我贴出来了

   

Java HotSpot(TM) 64-Bit Server VM (25.171-b11) for windows-amd64 JRE (1.8.0_171-b11), built on Mar 28 2018 16:06:12 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16657512k(4880600k free), swap 49163368k(22854332k free)
CommandLine flags: -XX:CompressedClassSpaceSize=62914560 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=D:\indigoProject\LinkScape\testFolder\guobao\sourceFile -XX:InitialHeapSize=268435456 -XX:MaxHeapSize=268435456 -XX:MaxMetaspaceSize=71303168 -XX:MetaspaceSize=71303168 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC
5.101: [GC (Allocation Failure) [PSYoungGen: 65536K->3405K(76288K)] 65536K->3413K(251392K), 0.0126293 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
6.415: [GC (Allocation Failure) [PSYoungGen: 68941K->3432K(76288K)] 68949K->3448K(251392K), 0.0056732 secs] [Times: user=0.05 sys=0.02, real=0.01 secs]
9.191: [GC (Allocation Failure) [PSYoungGen: 68968K->5096K(76288K)] 68984K->5120K(251392K), 0.0076425 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
10.421: [GC (Allocation Failure) [PSYoungGen: 70632K->5720K(76288K)] 70656K->5752K(251392K), 0.0086860 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
12.625: [GC (Allocation Failure) [PSYoungGen: 71256K->6680K(76288K)] 71288K->6720K(251392K), 0.0105985 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
13.728: [GC (Allocation Failure) [PSYoungGen: 72216K->7324K(77312K)] 72256K->7372K(252416K), 0.0091171 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
15.693: [GC (Allocation Failure) [PSYoungGen: 76956K->4928K(78336K)] 77004K->8296K(253440K), 0.0106936 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
16.981: [GC (Allocation Failure) [PSYoungGen: 74560K->3328K(78848K)] 77928K->9032K(253952K), 0.0085366 secs] [Times: user=0.03 sys=0.02, real=0.01 secs]
18.732: [GC (Allocation Failure) [PSYoungGen: 73984K->2496K(78848K)] 79688K->9858K(253952K), 0.0073972 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
20.078: [GC (Allocation Failure) [PSYoungGen: 73152K->1600K(77824K)] 80514K->10562K(252928K), 0.0046807 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
21.494: [GC (Allocation Failure) [PSYoungGen: 71232K->848K(78336K)] 80194K->11334K(253440K), 0.0034924 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
22.789: [GC (Allocation Failure) [PSYoungGen: 70480K->768K(78336K)] 80966K->11982K(253440K), 0.0020502 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
24.130: [GC (Allocation Failure) [PSYoungGen: 70400K->816K(78336K)] 81614K->12726K(253440K), 0.0024386 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
25.435: [GC (Allocation Failure) [PSYoungGen: 70448K->672K(78336K)] 82358K->13286K(253440K), 0.0019981 secs] [Times: user=0.05 sys=0.01, real=0.00 secs]
26.782: [GC (Allocation Failure) [PSYoungGen: 70304K->704K(78336K)] 82918K->13966K(253440K), 0.0017985 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
28.012: [GC (Allocation Failure) [PSYoungGen: 70336K->704K(78336K)] 83598K->14598K(253440K), 0.0020085 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
29.202: [GC (Allocation Failure) [PSYoungGen: 70336K->672K(78336K)] 84230K->15174K(253440K), 0.0026793 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
30.360: [GC (Allocation Failure) [PSYoungGen: 70304K->704K(78848K)] 84806K->15814K(253952K), 0.0020223 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
31.494: [GC (Allocation Failure) [PSYoungGen: 71360K->672K(78848K)] 86470K->16374K(253952K), 0.0019185 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
32.613: [GC (Allocation Failure) [PSYoungGen: 71328K->640K(79360K)] 87030K->16926K(254464K), 0.0027215 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
33.801: [GC (Allocation Failure) [PSYoungGen: 72320K->672K(79360K)] 88606K->17534K(254464K), 0.0020780 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
34.946: [GC (Allocation Failure) [PSYoungGen: 72352K->680K(80384K)] 89214K->18110K(255488K), 0.0023864 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
36.077: [GC (Allocation Failure) [PSYoungGen: 73896K->640K(79872K)] 91326K->18670K(254976K), 0.0023509 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
37.287: [GC (Allocation Failure) [PSYoungGen: 73856K->608K(80896K)] 91886K->19198K(256000K), 0.0027587 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
38.478: [GC (Allocation Failure) [PSYoungGen: 74848K->672K(80384K)] 93438K->19798K(255488K), 0.0021026 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
39.557: [GC (Allocation Failure) [PSYoungGen: 74912K->640K(81408K)] 94038K->20342K(256512K), 0.0018315 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
40.650: [GC (Allocation Failure) [PSYoungGen: 75904K->608K(80896K)] 95606K->20846K(256000K), 0.0018708 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
41.698: [GC (Allocation Failure) [PSYoungGen: 75872K->608K(81920K)] 96110K->21390K(257024K), 0.0019732 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
42.799: [GC (Allocation Failure) [PSYoungGen: 76896K->576K(81408K)] 97678K->21878K(256512K), 0.0031073 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
43.892: [GC (Allocation Failure) [PSYoungGen: 76864K->672K(82432K)] 98166K->22534K(257536K), 0.0034619 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
45.120: [GC (Allocation Failure) [PSYoungGen: 77984K->608K(81920K)] 99846K->23046K(257024K), 0.0028213 secs] [Times: user=0.05 sys=0.02, real=0.00 secs]
46.233: [GC (Allocation Failure) [PSYoungGen: 77920K->576K(82944K)] 100358K->23534K(258048K), 0.0024761 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
47.381: [GC (Allocation Failure) [PSYoungGen: 78912K->544K(82432K)] 101870K->24014K(257536K), 0.0028066 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
48.389: [GC (Allocation Failure) [PSYoungGen: 78880K->608K(83456K)] 102350K->24582K(258560K), 0.0024857 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
48.498: [GC (Metadata GC Threshold) [PSYoungGen: 24595K->224K(82944K)] 48569K->24694K(258048K), 0.0024885 secs] [Times: user=0.00 sys=0.02, real=0.00 secs]
48.500: [Full GC (Metadata GC Threshold) [PSYoungGen: 224K->0K(82944K)] [ParOldGen: 24470K->23707K(175104K)] 24694K->23707K(258048K), [Metaspace: 69014K->69014K(1114112K)], 0.3482776 secs] [Times: user=0.94 sys=0.02, real=0.35 secs]
48.848: [GC (Last ditch collection) [PSYoungGen: 0K->0K(83456K)] 23707K->23707K(258560K), 0.0010140 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
48.850: [Full GC (Last ditch collection) [PSYoungGen: 0K->0K(83456K)] [ParOldGen: 23707K->11368K(175104K)] 23707K->11368K(258560K), [Metaspace: 69014K->68867K(1114112K)], 0.0952605 secs] [Times: user=0.33 sys=0.00, real=0.10 secs]
49.052: [GC (Metadata GC Threshold) [PSYoungGen: 1590K->128K(83456K)] 12958K->11496K(258560K), 0.0017742 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
49.054: [Full GC (Metadata GC Threshold) [PSYoungGen: 128K->0K(83456K)] [ParOldGen: 11368K->11363K(175104K)] 11496K->11363K(258560K), [Metaspace: 68867K->68867K(1114112K)], 0.1009133 secs] [Times: user=0.31 sys=0.00, real=0.10 secs]
49.155: [GC (Last ditch collection) [PSYoungGen: 0K->0K(83968K)] 11363K->11363K(259072K), 0.0012378 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
49.157: [Full GC (Last ditch collection) [PSYoungGen: 0K->0K(83968K)] [ParOldGen: 11363K->11363K(175104K)] 11363K->11363K(259072K), [Metaspace: 68867K->68867K(1114112K)], 0.0368071 secs] [Times: user=0.13 sys=0.00, real=0.04 secs]
49.195: [GC (Metadata GC Threshold) [PSYoungGen: 1222K->64K(83456K)] 12586K->11427K(258560K), 0.0018324 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
49.197: [Full GC (Metadata GC Threshold) [PSYoungGen: 64K->0K(83456K)] [ParOldGen: 11363K->11359K(175104K)] 11427K->11359K(258560K), [Metaspace: 68867K->68867K(1114112K)], 0.0325830 secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
49.229: [GC (Last ditch collection) [PSYoungGen: 0K->0K(83968K)] 11359K->11359K(259072K), 0.0009879 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
49.230: [Full GC (Last ditch collection) [PSYoungGen: 0K->0K(83968K)] [ParOldGen: 11359K->11359K(175104K)] 11359K->11359K(259072K), [Metaspace: 68867K->68867K(1114112K)], 0.0388890 secs] [Times: user=0.11 sys=0.00, real=0.04 secs]
49.270: [GC (Metadata GC Threshold) [PSYoungGen: 0K->0K(83968K)] 11359K->11359K(259072K), 0.0012192 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
49.271: [Full GC (Metadata GC Threshold) [PSYoungGen: 0K->0K(83968K)] [ParOldGen: 11359K->11358K(175104K)] 11359K->11358K(259072K), [Metaspace: 68867K->68867K(1114112K)], 0.1153955 secs] [Times: user=0.28 sys=0.00, real=0.12 secs]
49.387: [GC (Last ditch collection) [PSYoungGen: 0K->0K(84480K)] 11358K->11358K(259584K), 0.0009881 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
49.388: [Full GC (Last ditch collection) [PSYoungGen: 0K->0K(84480K)] [ParOldGen: 11358K->11358K(175104K)] 11358K->11358K(259584K), [Metaspace: 68867K->68867K(1114112K)], 0.0276961 secs] [Times: user=0.08 sys=0.00, real=0.03 secs]
49.416: [GC (Metadata GC Threshold) [PSYoungGen: 1244K->128K(83968K)] 12603K->11486K(259072K), 0.0011793 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
49.417: [Full GC (Metadata GC Threshold) [PSYoungGen: 128K->0K(83968K)] [ParOldGen: 11358K->11359K(175104K)] 11486K->11359K(259072K), [Metaspace: 68869K->68869K(1114112K)], 0.0972575 secs] [Times: user=0.36 sys=0.00, real=0.10 secs]
49.515: [GC (Last ditch collection) [PSYoungGen: 0K->0K(84480K)] 11359K->11359K(259584K), 0.0009651 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
49.516: [Full GC (Last ditch collection) [PSYoungGen: 0K->0K(84480K)] [ParOldGen: 11359K->11359K(175104K)] 11359K->11359K(259584K), [Metaspace: 68869K->68869K(1114112K)], 0.0283726 secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
49.547: [GC (Metadata GC Threshold) [PSYoungGen: 1631K->64K(84480K)] 12990K->11423K(259584K), 0.0019427 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
49.549: [Full GC (Metadata GC Threshold) [PSYoungGen: 64K->0K(84480K)] [ParOldGen: 11359K->11373K(175104K)] 11423K->11373K(259584K), [Metaspace: 68871K->68871K(1114112K)], 0.1218152 secs] [Times: user=0.31 sys=0.00, real=0.12 secs]
49.671: [GC (Last ditch collection) [PSYoungGen: 0K->0K(84992K)] 11373K->11373K(260096K), 0.0011670 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
49.672: [Full GC (Last ditch collection) [PSYoungGen: 0K->0K(84992K)] [ParOldGen: 11373K->11367K(175104K)] 11373K->11367K(260096K), [Metaspace: 68871K->68871K(1114112K)], 0.0325638 secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
49.705: [GC (Metadata GC Threshold) [PSYoungGen: 397K->128K(84992K)] 11764K->11495K(260096K), 0.0009596 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
49.706: [Full GC (Metadata GC Threshold) [PSYoungGen: 128K->0K(84992K)] [ParOldGen: 11367K->11364K(175104K)] 11495K->11364K(260096K), [Metaspace: 68871K->68871K(1114112K)], 0.0288354 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]
49.735: [GC (Last ditch collection) [PSYoungGen: 0K->0K(84992K)] 11364K->11364K(260096K), 0.0009065 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
49.736: [Full GC (Last ditch collection) [PSYoungGen: 0K->0K(84992K)] [ParOldGen: 11364K->11364K(175104K)] 11364K->11364K(260096K), [Metaspace: 68871K->68871K(1114112K)], 0.0282498 secs] [Times: user=0.08 sys=0.00, real=0.03 secs]
49.765: [GC (Metadata GC Threshold) [PSYoungGen: 1267K->96K(84992K)] 12631K->11460K(260096K), 0.0010034 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
49.766: [Full GC (Metadata GC Threshold) [PSYoungGen: 96K->0K(84992K)] [ParOldGen: 11364K->11366K(175104K)] 11460K->11366K(260096K), [Metaspace: 68871K->68871K(1114112K)], 0.0274981 secs] [Times: user=0.02 sys=0.00, real=0.03 secs]
49.793: [GC (Last ditch collection) [PSYoungGen: 0K->0K(85504K)] 11366K->11366K(260608K), 0.0009064 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
49.794: [Full GC (Last ditch collection) [PSYoungGen: 0K->0K(85504K)] [ParOldGen: 11366K->11365K(175104K)] 11366K->11365K(260608K), [Metaspace: 68871K->68871K(1114112K)], 0.0406365 secs] [Times: user=0.08 sys=0.00, real=0.04 secs]
49.835: [GC (Metadata GC Threshold) [PSYoungGen: 1271K->32K(84992K)] 12637K->11397K(260096K), 0.0009762 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
49.836: [Full GC (Metadata GC Threshold) [PSYoungGen: 32K->0K(84992K)] [ParOldGen: 11365K->11366K(175104K)] 11397K->11366K(260096K), [Metaspace: 68871K->68871K(1114112K)], 0.0287186 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]
49.865: [GC (Last ditch collection) [PSYoungGen: 0K->0K(85504K)] 11366K->11366K(260608K), 0.0009453 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
49.866: [Full GC (Last ditch collection) [PSYoungGen: 0K->0K(85504K)] [ParOldGen: 11366K->11366K(175104K)] 11366K->11366K(260608K), [Metaspace: 68871K->68871K(1114112K)], 0.0294249 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]
49.897: [GC (Metadata GC Threshold) [PSYoungGen: 2566K->128K(85504K)] 13932K->11494K(260608K), 0.0010616 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
49.898: [Full GC (Metadata GC Threshold) [PSYoungGen: 128K->0K(85504K)] [ParOldGen: 11366K->11259K(175104K)] 11494K->11259K(260608K), [Metaspace: 68880K->68880K(1114112K)], 0.1465769 secs] [Times: user=0.49 sys=0.00, real=0.15 secs]
50.045: [GC (Last ditch collection) [PSYoungGen: 0K->0K(85504K)] 11259K->11259K(260608K), 0.0021317 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
50.047: [Full GC (Last ditch collection) [PSYoungGen: 0K->0K(85504K)] [ParOldGen: 11259K->11242K(175104K)] 11259K->11242K(260608K), [Metaspace: 68880K->68880K(1114112K)], 0.0318108 secs] [Times: user=0.05 sys=0.00, real=0.03 secs]
50.080: [GC (Metadata GC Threshold) [PSYoungGen: 396K->64K(85504K)] 11639K->11306K(260608K), 0.0024672 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
50.082: [Full GC (Metadata GC Threshold) [PSYoungGen: 64K->0K(85504K)] [ParOldGen: 11242K->11236K(175104K)] 11306K->11236K(260608K), [Metaspace: 68880K->68880K(1114112K)], 0.0353489 secs] [Times: user=0.08 sys=0.00, real=0.04 secs]
50.118: [GC (Last ditch collection) [PSYoungGen: 0K->0K(86016K)] 11236K->11236K(261120K), 0.0011646 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
50.119: [Full GC (Last ditch collection) [PSYoungGen: 0K->0K(86016K)] [ParOldGen: 11236K->11236K(175104K)] 11236K->11236K(261120K), [Metaspace: 68880K->68880K(1114112K)], 0.0299239 secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
50.149: [GC (Metadata GC Threshold) [PSYoungGen: 849K->96K(85504K)] 12086K->11332K(260608K), 0.0012139 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
50.150: [Full GC (Metadata GC Threshold) [PSYoungGen: 96K->0K(85504K)] [ParOldGen: 11236K->11237K(175104K)] 11332K->11237K(260608K), [Metaspace: 68880K->68880K(1114112K)], 0.0338103 secs] [Times: user=0.08 sys=0.00, real=0.03 secs]
50.184: [GC (Last ditch collection) [PSYoungGen: 0K->0K(86016K)] 11237K->11237K(261120K), 0.0010343 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
50.185: [Full GC (Last ditch collection) [PSYoungGen: 0K->0K(86016K)] [ParOldGen: 11237K->11226K(175104K)] 11237K->11226K(261120K), [Metaspace: 68880K->68880K(1114112K)], 0.0325331 secs] [Times: user=0.08 sys=0.00, real=0.03 secs]
50.219: [GC (Metadata GC Threshold) [PSYoungGen: 850K->64K(86016K)] 12076K->11290K(261120K), 0.0010981 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
50.220: [Full GC (Metadata GC Threshold) [PSYoungGen: 64K->0K(86016K)] [ParOldGen: 11226K->11224K(175104K)] 11290K->11224K(261120K), [Metaspace: 68884K->68884K(1114112K)], 0.0332821 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
50.253: [GC (Last ditch collection) [PSYoungGen: 0K->0K(86016K)] 11224K->11224K(261120K), 0.0011355 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
50.254: [Full GC (Last ditch collection) [PSYoungGen: 0K->0K(86016K)] [ParOldGen: 11224K->11224K(175104K)] 11224K->11224K(261120K), [Metaspace: 68884K->68884K(1114112K)], 0.0332115 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
50.289: [GC (Metadata GC Threshold) [PSYoungGen: 421K->96K(86016K)] 11645K->11320K(261120K), 0.0010384 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
50.290: [Full GC (Metadata GC Threshold) [PSYoungGen: 96K->0K(86016K)] [ParOldGen: 11224K->11242K(175104K)] 11320K->11242K(261120K), [Metaspace: 68884K->68884K(1114112K)], 0.0317665 secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
50.322: [GC (Last ditch collection) [PSYoungGen: 0K->0K(86016K)] 11242K->11242K(261120K), 0.0008965 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
50.323: [Full GC (Last ditch collection) [PSYoungGen: 0K->0K(86016K)] [ParOldGen: 11242K->11227K(175104K)] 11242K->11227K(261120K), [Metaspace: 68884K->68881K(1114112K)], 0.0409731 secs] [Times: user=0.14 sys=0.00, real=0.04 secs]
50.364: [GC (Metadata GC Threshold) [PSYoungGen: 404K->96K(86016K)] 11631K->11323K(261120K), 0.0011994 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
50.365: [Full GC (Metadata GC Threshold) [PSYoungGen: 96K->0K(86016K)] [ParOldGen: 11227K->11221K(175104K)] 11323K->11221K(261120K), [Metaspace: 68881K->68881K(1114112K)], 0.0298713 secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
50.395: [GC (Last ditch collection) [PSYoungGen: 0K->0K(86016K)] 11221K->11221K(261120K), 0.0014522 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
50.397: [Full GC (Last ditch collection) [PSYoungGen: 0K->0K(86016K)] [ParOldGen: 11221K->11221K(175104K)] 11221K->11221K(261120K), [Metaspace: 68881K->68881K(1114112K)], 0.0427857 secs] [Times: user=0.16 sys=0.02, real=0.04 secs]
50.443: [GC (Metadata GC Threshold) [PSYoungGen: 869K->96K(86016K)] 12091K->11317K(261120K), 0.0010048 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
50.444: [Full GC (Metadata GC Threshold) [PSYoungGen: 96K->0K(86016K)] [ParOldGen: 11221K->11227K(175104K)] 11317K->11227K(261120K), [Metaspace: 68881K->68881K(1114112K)], 0.0513194 secs] [Times: user=0.14 sys=0.00, real=0.05 secs]
50.495: [GC (Last ditch collection) [PSYoungGen: 0K->0K(86528K)] 11227K->11227K(261632K), 0.0014694 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
50.497: [Full GC (Last ditch collection) [PSYoungGen: 0K->0K(86528K)] [ParOldGen: 11227K->11226K(175104K)] 11227K->11226K(261632K), [Metaspace: 68881K->68881K(1114112K)], 0.0285380 secs] [Times: user=0.08 sys=0.00, real=0.03 secs]
50.526: [GC (Metadata GC Threshold) [PSYoungGen: 7K->96K(86528K)] 11234K->11322K(261632K), 0.0009894 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
50.527: [Full GC (Metadata GC Threshold) [PSYoungGen: 96K->0K(86528K)] [ParOldGen: 11226K->11228K(175104K)] 11322K->11228K(261632K), [Metaspace: 68881K->68881K(1114112K)], 0.0290601 secs] [Times: user=0.08 sys=0.00, real=0.03 secs]
50.556: [GC (Last ditch collection) [PSYoungGen: 0K->0K(86528K)] 11228K->11228K(261632K), 0.0009976 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
50.557: [Full GC (Last ditch collection) [PSYoungGen: 0K->0K(86528K)] [ParOldGen: 11228K->11228K(175104K)] 11228K->11228K(261632K), [Metaspace: 68881K->68881K(1114112K)], 0.0512065 secs] [Times: user=0.11 sys=0.00, real=0.05 secs]
Heap
 PSYoungGen      total 86528K, used 410K [0x00000000fab00000, 0x0000000100000000, 0x0000000100000000)
  eden space 86016K, 0% used [0x00000000fab00000,0x00000000fab66a08,0x00000000fff00000)
  from space 512K, 0% used [0x00000000fff80000,0x00000000fff80000,0x0000000100000000)
  to   space 512K, 0% used [0x00000000fff00000,0x00000000fff00000,0x00000000fff80000)
 ParOldGen       total 175104K, used 11228K [0x00000000f0000000, 0x00000000fab00000, 0x00000000fab00000)
  object space 175104K, 6% used [0x00000000f0000000,0x00000000f0af7040,0x00000000fab00000)
 Metaspace       used 68883K, capacity 69166K, committed 69632K, reserved 1114112K
  class space    used 5574K, capacity 5670K, committed 5760K, reserved 1048576K

GC 日志

里面有两种 GC 日志格式:

第一种:

[GC (Allocation Failure) [PSYoungGen: 65536K->3405K(76288K)] 65536K->3413K(251392K), 0.0126293 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
[GC类型(GC原因)[新生代垃圾收集器:gc前新生代的内存使用情况(eden+from)->gc后新生代的内存使用情况(新生代总内存(eden+from))]gc前堆内存的使用情况->gc后堆内存的使用情况(堆总内存), gc耗时] [Times: gc阶段用户空间耗时 gc阶段内核空间耗时, gc阶段实际耗时]

第二种:

[Full GC (Metadata GC Threshold) [PSYoungGen: 96K->0K(86016K)] [ParOldGen: 11227K->11221K(175104K)] 11323K->11221K(261120K), [Metaspace: 68881K->68881K(1114112K)], 0.0298713 secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
[GC类型 (GC原因) [新生代垃圾收集器: gc前新生代的内存使用情况->gc后新生代的内存使用情况(新生代总内存)] [老年代垃圾收集器: gc前老年代的内存使用情况->gc后老年代的内存使用情况(老年代总内存)] gc前堆内存的使用情况->gc后堆内存的使用情况(堆总内存), [Metaspace: gc前元空间的内存使用情况->gc后元空间的内存使用情况(元空间总内存)], gc耗时] [Times: gc阶段用户空间耗时 gc阶段内核空间耗时, gc阶段实际耗时]

最后在抛出 OOM 之后输出此时堆和元空间的内存大小:

Heap
 PSYoungGen      total 86528K(enden+from), used 410K(和图形上的Eden Space一致) [0x00000000fab00000, 0x0000000100000000, 0x0000000100000000)
  eden space 86016K, 0% used [0x00000000fab00000,0x00000000fab66a08,0x00000000fff00000)
  from space 512K, 0% used [0x00000000fff80000,0x00000000fff80000,0x0000000100000000)
  to   space 512K, 0% used [0x00000000fff00000,0x00000000fff00000,0x00000000fff80000)
 ParOldGen       total 175104K, used 11228K [0x00000000f0000000, 0x00000000fab00000, 0x00000000fab00000)
  object space 175104K, 6% used [0x00000000f0000000,0x00000000f0af7040,0x00000000fab00000)
 Metaspace       used 68883K, capacity 69166K, committed 69632K, reserved 1114112K
  class space    used 5574K, capacity 5670K, committed 5760K, reserved 1048576K

主要调优的参数:

-XX:MetaspaceSize
-XX:MaxMetaspaceSize

调优原则

1、最大、最小设置成一样大防止内存动态扩展

2、程序运行起来后,通过 visualVM、arthas 查看占用了多少内存,向上调优,预留 20%以上的空间

通过 gc 日志和 visualVM 可以看到 Eden,s0,s1 区的内存是动态变化的。这是因为新生代使用的垃圾收集器 PSYoungGen 代表 ParallelGC 垃圾收集器,它是一个追求系统吞吐量的垃圾收集器,它有一个参数:-XX:UseAdaptiveSizePolicy

默认是开启的,表示自适应 GC 模式,垃圾回收器将自动调整年轻代、老年代等参数,达到吞吐量、堆大小、停顿时间之间的平衡。一般用于,手动调整参数比较困难的场景,让收集器自动进行调整。

关于 gc 日志最后的一段内容: Metaspace used 68883K, capacity 69166K, committed 69632K, reserved 1114112K 。每个内容代表什么内容也是很重要的一部分知识,这里先展开讲述,后面单独讲这部分。

3)堆区 OOM

测试代码:

   

int[] intArr = new int[10];
            List<MytestwebApplicationTests> objs = new ArrayList<>();

            for (;;) {
                try {
                    Thread.sleep(1);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }

                objs.add(new MytestwebApplicationTests());
            }

测试代码

gc 日志:

   

Java HotSpot(TM) 64-Bit Server VM (25.171-b11) for windows-amd64 JRE (1.8.0_171-b11), built on Mar 28 2018 16:06:12 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16657512k(4457476k free), swap 49163368k(21068572k free)
CommandLine flags: -XX:CompressedClassSpaceSize=62914560 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=D:\indigoProject\LinkScape\testFolder\guobao\sourceFile -XX:InitialHeapSize=10485760 -XX:MaxHeapSize=10485760 -XX:MaxMetaspaceSize=71303168 -XX:MetaspaceSize=71303168 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC
0.428: [GC (Allocation Failure) [PSYoungGen: 2048K->508K(2560K)] 2048K->984K(9728K), 0.0015592 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
5.954: [GC (Allocation Failure) [PSYoungGen: 2556K->488K(2560K)] 3032K->1321K(9728K), 0.0011141 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
6.045: [GC (Allocation Failure) [PSYoungGen: 2536K->508K(2560K)] 3369K->1672K(9728K), 0.0023201 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
6.588: [GC (Allocation Failure) [PSYoungGen: 2556K->492K(2560K)] 3720K->1960K(9728K), 0.0012657 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
6.665: [GC (Allocation Failure) [PSYoungGen: 2540K->492K(2560K)] 4008K->2340K(9728K), 0.0017305 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
7.239: [GC (Allocation Failure) [PSYoungGen: 2540K->492K(1536K)] 4388K->2761K(8704K), 0.0030774 secs] [Times: user=0.06 sys=0.00, real=0.00 secs]
9.266: [GC (Allocation Failure) [PSYoungGen: 1516K->432K(2048K)] 3785K->3017K(9216K), 0.0018632 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
15.268: [GC (Allocation Failure) [PSYoungGen: 1456K->420K(2048K)] 4041K->3101K(9216K), 0.0011105 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
22.268: [GC (Allocation Failure) [PSYoungGen: 1444K->374K(2048K)] 4125K->3192K(9216K), 0.0010120 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
29.386: [GC (Allocation Failure) [PSYoungGen: 1398K->306K(2048K)] 4216K->3331K(9216K), 0.0013355 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
38.277: [GC (Allocation Failure) [PSYoungGen: 1330K->128K(2048K)] 4355K->3395K(9216K), 0.0020058 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
44.284: [GC (Allocation Failure) [PSYoungGen: 1152K->283K(2048K)] 4419K->3655K(9216K), 0.0009829 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
52.288: [GC (Allocation Failure) [PSYoungGen: 1307K->128K(2048K)] 4679K->3711K(9216K), 0.0010639 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
59.287: [GC (Allocation Failure) [PSYoungGen: 1152K->313K(2048K)] 4735K->3984K(9216K), 0.0021038 secs] [Times: user=0.03 sys=0.02, real=0.00 secs]
67.291: [GC (Allocation Failure) [PSYoungGen: 1337K->160K(2048K)] 5008K->4104K(9216K), 0.0012702 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
75.296: [GC (Allocation Failure) [PSYoungGen: 1184K->128K(2048K)] 5128K->4160K(9216K), 0.0013662 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
83.307: [GC (Allocation Failure) [PSYoungGen: 1152K->160K(2048K)] 5184K->4288K(9216K), 0.0014977 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
89.299: [GC (Allocation Failure) [PSYoungGen: 1184K->437K(2048K)] 5312K->4662K(9216K), 0.0012284 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
97.314: [GC (Allocation Failure) [PSYoungGen: 1461K->128K(2048K)] 5686K->4710K(9216K), 0.0011155 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
106.307: [GC (Allocation Failure) [PSYoungGen: 1152K->192K(2048K)] 5734K->4862K(9216K), 0.0013460 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
114.310: [GC (Allocation Failure) [PSYoungGen: 1216K->160K(2048K)] 5886K->4934K(9216K), 0.0012923 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
122.316: [GC (Allocation Failure) [PSYoungGen: 1184K->192K(2048K)] 5958K->5046K(9216K), 0.0012928 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
127.317: [GC (Allocation Failure) [PSYoungGen: 1216K->544K(2048K)] 6070K->5487K(9216K), 0.0015028 secs] [Times: user=0.06 sys=0.00, real=0.00 secs]
135.334: [GC (Allocation Failure) [PSYoungGen: 1568K->128K(2048K)] 6511K->5551K(9216K), 0.0021384 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
144.324: [GC (Allocation Failure) [PSYoungGen: 1152K->192K(2048K)] 6575K->5695K(9216K), 0.0015513 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
152.339: [GC (Allocation Failure) [PSYoungGen: 1216K->128K(2048K)] 6719K->5727K(9216K), 0.0017518 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
161.330: [GC (Allocation Failure) [PSYoungGen: 1152K->192K(2048K)] 6751K->5887K(9216K), 0.0016048 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
169.346: [GC (Allocation Failure) [PSYoungGen: 1216K->160K(2048K)] 6911K->5951K(9216K), 0.0015451 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
178.336: [GC (Allocation Failure) [PSYoungGen: 1184K->160K(2048K)] 6975K->6039K(9216K), 0.0015526 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
186.357: [GC (Allocation Failure) [PSYoungGen: 1184K->128K(2048K)] 7063K->6103K(9216K), 0.0019706 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
189.417: [GC (Allocation Failure) [PSYoungGen: 1152K->753K(2048K)] 7127K->6816K(9216K), 0.0014603 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
198.349: [GC (Allocation Failure) [PSYoungGen: 1777K->128K(2048K)] 7840K->6872K(9216K), 0.0022700 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
198.352: [Full GC (Ergonomics) [PSYoungGen: 128K->0K(2048K)] [ParOldGen: 6744K->4596K(7168K)] 6872K->4596K(9216K), [Metaspace: 9423K->9357K(1058816K)], 0.0704926 secs] [Times: user=0.14 sys=0.00, real=0.07 secs]
206.352: [GC (Allocation Failure) [PSYoungGen: 1024K->128K(2048K)] 5620K->4732K(9216K), 0.0012006 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
214.355: [GC (Allocation Failure) [PSYoungGen: 1152K->224K(2048K)] 5756K->4828K(9216K), 0.0016980 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
222.367: [GC (Allocation Failure) [PSYoungGen: 1248K->288K(2048K)] 5852K->4892K(9216K), 0.0017520 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
231.359: [GC (Allocation Failure) [PSYoungGen: 1312K->384K(2048K)] 5916K->4988K(9216K), 0.0021191 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
239.363: [GC (Allocation Failure) [PSYoungGen: 1408K->448K(2048K)] 6012K->5052K(9216K), 0.0036738 secs] [Times: user=0.05 sys=0.00, real=0.00 secs]
247.366: [GC (Allocation Failure) [PSYoungGen: 1472K->544K(2048K)] 6076K->5156K(9216K), 0.0050299 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
255.370: [GC (Allocation Failure) [PSYoungGen: 1568K->544K(2048K)] 6180K->5260K(9216K), 0.0036398 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
263.390: [GC (Allocation Failure) [PSYoungGen: 1568K->512K(2048K)] 6284K->5324K(9216K), 0.0035550 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
271.667: [GC (Allocation Failure) [PSYoungGen: 1536K->416K(2048K)] 6348K->5404K(9216K), 0.0043608 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
280.380: [GC (Allocation Failure) [PSYoungGen: 1440K->352K(2048K)] 7366K->6422K(9216K), 0.0034423 secs] [Times: user=0.05 sys=0.02, real=0.00 secs]
288.400: [GC (Allocation Failure) [PSYoungGen: 1376K->320K(2048K)] 7446K->6542K(9216K), 0.0023892 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
297.388: [GC (Allocation Failure) [PSYoungGen: 1344K->320K(2048K)] 7566K->6638K(9216K), 0.0023476 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
305.408: [GC (Allocation Failure) [PSYoungGen: 1344K->288K(2048K)] 7662K->6694K(9216K), 0.0026645 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
312.410: [GC (Allocation Failure) [PSYoungGen: 1312K->352K(2048K)] 7718K->6846K(9216K), 0.0023412 secs] [Times: user=0.06 sys=0.00, real=0.00 secs]
321.395: [GC (Allocation Failure) [PSYoungGen: 1376K->320K(2048K)] 7870K->6902K(9216K), 0.0024090 secs] [Times: user=0.06 sys=0.00, real=0.00 secs]
329.402: [GC (Allocation Failure) [PSYoungGen: 1344K->416K(2048K)] 7926K->6998K(9216K), 0.0023041 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
337.410: [GC (Allocation Failure) [PSYoungGen: 1440K->480K(2048K)] 8022K->7062K(9216K), 0.0027981 secs] [Times: user=0.06 sys=0.00, real=0.00 secs]
345.432: [GC (Allocation Failure) [PSYoungGen: 1504K->544K(2048K)] 8086K->7126K(9216K), 0.0035824 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
354.416: [GC (Allocation Failure) [PSYoungGen: 1568K->544K(2048K)] 8150K->7214K(9216K), 0.0039511 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
362.423: [GC (Allocation Failure) [PSYoungGen: 1568K->512K(2048K)] 8238K->7278K(9216K), 0.0036294 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
370.427: [GC (Allocation Failure) [PSYoungGen: 1536K->512K(2048K)] 8302K->7366K(9216K), 0.0038899 secs] [Times: user=0.05 sys=0.00, real=0.00 secs]
370.431: [Full GC (Ergonomics) [PSYoungGen: 512K->0K(2048K)] [ParOldGen: 6854K->6347K(7168K)] 7366K->6347K(9216K), [Metaspace: 9426K->9334K(1058816K)], 0.1011058 secs] [Times: user=0.17 sys=0.00, real=0.10 secs]
374.427: [GC (Allocation Failure) [PSYoungGen: 1024K->288K(2048K)] 7371K->6643K(9216K), 0.0024651 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
382.434: [GC (Allocation Failure) [PSYoungGen: 1312K->224K(2048K)] 7667K->6587K(9216K), 0.0014437 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
390.437: [GC (Allocation Failure) [PSYoungGen: 1248K->352K(2048K)] 7611K->6723K(9216K), 0.0016985 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
398.440: [GC (Allocation Failure) [PSYoungGen: 1376K->416K(2048K)] 7747K->6787K(9216K), 0.0021561 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
406.455: [GC (Allocation Failure) [PSYoungGen: 1440K->448K(2048K)] 7811K->6827K(9216K), 0.0025337 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
415.149: [GC (Allocation Failure) [PSYoungGen: 1472K->544K(2048K)] 7851K->6931K(9216K), 0.0037714 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
416.106: [GC (Allocation Failure) [PSYoungGen: 682K->544K(2048K)] 7069K->6931K(9216K), 0.0035274 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
416.110: [GC (Allocation Failure) [PSYoungGen: 544K->544K(2048K)] 6931K->6931K(9216K), 0.0035866 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
416.114: [Full GC (Allocation Failure) [PSYoungGen: 544K->0K(2048K)] [ParOldGen: 6387K->6788K(7168K)] 6931K->6788K(9216K), [Metaspace: 9420K->9420K(1058816K)], 0.0928162 secs] [Times: user=0.24 sys=0.00, real=0.09 secs]
416.207: [GC (Allocation Failure) [PSYoungGen: 0K->0K(2048K)] 6788K->6788K(9216K), 0.0004495 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
416.207: [Full GC (Allocation Failure) [PSYoungGen: 0K->0K(2048K)] [ParOldGen: 6788K->6752K(7168K)] 6788K->6752K(9216K), [Metaspace: 9420K->9343K(1058816K)], 0.0539839 secs] [Times: user=0.20 sys=0.00, real=0.05 secs]
Heap
 PSYoungGen      total 2048K, used 26K [0x00000000ffd00000, 0x0000000100000000, 0x0000000100000000)
  eden space 1024K, 2% used [0x00000000ffd00000,0x00000000ffd06aa0,0x00000000ffe00000)
  from space 1024K, 0% used [0x00000000fff00000,0x00000000fff00000,0x0000000100000000)
  to   space 1024K, 0% used [0x00000000ffe00000,0x00000000ffe00000,0x00000000fff00000)
 ParOldGen       total 7168K, used 6752K [0x00000000ff600000, 0x00000000ffd00000, 0x00000000ffd00000)
  object space 7168K, 94% used [0x00000000ff600000,0x00000000ffc980c8,0x00000000ffd00000)
 Metaspace       used 9361K, capacity 9594K, committed 9984K, reserved 1058816K
  class space    used 1067K, capacity 1152K, committed 1280K, reserved 1048576K

GC 日志

最后抛出的异常:
 

visualVM 中最后的显示:

 
 

可以看到明显和 Metaspace 中 OOM 表现完全不同,old Gen 发生 4 次,YGC 发生 62 次,对象一直在向 old 区域移动,从 Full GC 日志可以看出:

[Full GC (Ergonomics) [PSYoungGen: 128K->0K(2048K)] [ParOldGen: 6744K->4596K(7168K)] 6872K->4596K(9216K), [Metaspace: 9423K->9357K(1058816K)], 0.0704926 secs] [Times: user=0.14 sys=0.00, real=0.07 secs]

OldGC 也就是 Full GC 时 Metaspace 也会发生垃圾回收。

调优参数

-Xms10m -Xmx10m

调优原则

1、预留 30%以上的空间

2、周期性看日志,重点关注 full gc 频率

4)虚拟机栈 OOM

测试代码:

   

private int val = 0;

    public void test() {
        val++;

        test();
    }

    public static void main(String[] args) {
        StackOverFlowTest test = new StackOverFlowTest();

        try {
            test.test();
        } catch (Throwable t) {
            t.printStackTrace();

            System.out.println(test.val);
        }
    }

测试代码

JVM 参数:-Xss 虚拟机栈大小,这个大小有最小的限制,和系统有关。

 
 
 
 

执行完程序会抛出栈溢出的异常:

 
 

这里输出了栈的深度:3099,而且设置的同一个栈大小多次执行抛错时得到栈深是不一样的。

 
 

这是因为有对象和轻量级锁会在栈上分配,导致栈深变小。而且我们还知道每次调用方法会创建一个栈帧放入栈内,我们可以大致推算栈帧的小 200 *1024/2709。

3:使用 visualVM 分析死锁

死锁代码:

   

/**
 * 一个简单的死锁类
 * 当DeadLock类的对象flag==1时(td1),先锁定o1,睡眠500毫秒
 * 而td1在睡眠的时候另一个flag==0的对象(td2)线程启动,先锁定o2,睡眠500毫秒
 * td1睡眠结束后需要锁定o2才能继续执行,而此时o2已被td2锁定;
 * td2睡眠结束后需要锁定o1才能继续执行,而此时o1已被td1锁定;
 * td1、td2相互等待,都需要得到对方锁定的资源才能继续执行,从而死锁。
 */
public class DeadLock implements Runnable {
    public int flag = 1;
    //静态对象是类的所有对象共享的
    private static Object o1 = new Object(), o2 = new Object();
    @Override
    public void run() {
        System.out.println("flag=" + flag);
        if (flag == 1) {
            synchronized (o1) {
                try {
                    Thread.sleep(500);
                } catch (Exception e) {
                    e.printStackTrace();
                }
                synchronized (o2) {
                    System.out.println("1");
                }
            }
        }
        if (flag == 0) {
            synchronized (o2) {
                try {
                    Thread.sleep(500);
                } catch (Exception e) {
                    e.printStackTrace();
                }
                synchronized (o1) {
                    System.out.println("0");
                }
            }
        }
    }

    public static void main(String[] args) {
        DeadLock td1 = new DeadLock();
        DeadLock td2 = new DeadLock();
        td1.flag = 1;
        td2.flag = 0;
        //td1,td2都处于可执行状态,但JVM线程调度先执行哪个线程是不确定的。
        //td2的run()可能在td1的run()之前运行
        new Thread(td1).start();
        new Thread(td2).start();
    }
}

死锁代码

代码运行起来在 visualVM 中的线程监控 tab 页可以看到已经有了提示:

 
 

点击线程 Dump:

 
 

可以看到死锁的位置就给你定位到了。是不是很方便。

4:分析 CPU 占用过高问题

这个主要在服务器上进行监控的时候或打印出来线程堆栈分析。

1)根据 top 命令,发现 PID 为 28555 的 Java 进程占用 CPU 高达 200%,出现故障。

通过 ps aux | grep PID 命令,可以进一步确定是 tomcat 进程出现了问题。但是,怎么定位到具体线程或者代码呢?

 
 

2)首先显示线程列表:

ps -mp pid -o THREAD,tid,time

找到了耗时最高的线程 28802,占用 CPU 时间快两个小时了!

 
 

其次将需要的线程 ID 转换为 16 进制格式:

printf "%x\n" tid
 
 

3)最后打印线程的堆栈信息:

jstack pid |grep tid -A 30

定位到问题查看代码

 
 

分析 CPU 占用过高另外一种方式,其实思路都是一样的,只是方式不同而且:

把线程 dump 出来,然后分析

1:Threaddump 的方法:使用命令把结果重定向到 threaddump.log 中

  • kill -3 pid > threaddump.log
  • jstack -l pid >threaddump.log
  • jvisualvm 中来 thread dump

2:找到导致 cpu 高的线程
top-H -p pid
PIDUSER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
4691 root 19 0 448m 132m 13m S 0.0 7.5 0:00.01 java
4692 root 19 0 448m 132m 13m S 0.0 7.5 0:00.39 java
4698 root 15 0 448m 132m 13m S 0.0 7.5 0:14.14 java
4699 root 15 0 448m 132m 13m S 0.0 7.5 0:00.43 java
4700 root 15 0 448m 132m 13m S 0.0 7.5 0:00.63 java
4701 root 18 0 448m 132m 13m S 0.0 7.5 0:00.00 java

对应的线程 id 是十进制的,需要转换为十六进制的在 threaddump 文件中才可以看到

3:十进制转十六进制
-bash-3.2# python

print hex(4739)
0×1283

4:找到对应的线程
vithreaddump.log
查找:/0×1283
找到对应的线程,把相关的方法找出来,可以精确到代码的行号,自己修改相关源码来 fix bug。

上次编辑于:
贡献者: Andy