一次超詭異的FGC,你之前肯定沒碰到過的場景,快Get起來

正擼著代碼,內部聊天工具彈出一條信息:“我這個機器總是頻繁FGC...快幫我看看

我打開對話框,機智的回覆一個表情:

一次超诡异的FGC,你之前肯定没碰到过的场景,快Get起来

繼續默默擼碼,代碼是我的命,一日不擼,就藍瘦。隨後,小夥伴砸了一段GC日誌過來:

  1. <code>2019-09-17T20:33:57.889+0800: 4753520.554: [Full GC (Metadata GC Threshold) 4753520.554: [CMS[YG occupancy: 723220 K (1887488 K)]4753520.988: [weak refs process ing, 0.0042134 secs]4753520.992: [classunloading, 0.0987343 secs]4753521.091: [scrub symbol table, 0.0237609 secs]4753521.115: [scrubstringtable, 0.0025983 s ecs]: 145423K->141376K(3354624K), 0.6260023 secs] 868644K->864597K(5242112K), [Metaspace: 128179K->128179K(1234944K)], 0.6264315 secs] [Times: user=1.24 sys=0.0 0, real=0.63 secs]/<code>

  2. <code>4159962 Heap after GC invocations=8029 (full 50):/<code>

  3. <code>4159963 par newgeneration total 1887488K, used 723220K [0x0000000673400000, 0x00000006f3400000, 0x00000006f3400000)/<code>

  4. <code>4159964 eden space 1677824K, 42% used [0x0000000673400000, 0x000000069ed59090, 0x00000006d9a80000)/<code>

  5. <code>4159965 fromspace 209664K, 4% used [0x00000006d9a80000, 0x00000006da36c210, 0x00000006e6740000)/<code>

  6. <code>4159966 to space 209664K, 0% used [0x00000006e6740000, 0x00000006e6740000, 0x00000006f3400000)/<code>

  7. <code>4159967 concurrent mark-sweep generation total 3354624K, used 141376K [0x00000006f3400000, 0x00000007c0000000, 0x00000007c0000000)/<code>

  8. <code>4159968 Metaspace used 128145K, capacity 136860K, committed 262144K, reserved 1234944K/<code>

  9. <code>4159969 class

    space used 14443K, capacity 16168K, committed 77312K, reserved 1048576K/<code>

  10. <code>4159970 }/<code>

  11. <code>4159971 {Heap before GC invocations=8029 (full 50):/<code>

  12. <code>4159972 par newgeneration total 1887488K, used 723220K [0x0000000673400000, 0x00000006f3400000, 0x00000006f3400000)/<code>

  13. <code>4159973 eden space 1677824K, 42% used [0x0000000673400000, 0x000000069ed59090, 0x00000006d9a80000)/<code>

  14. <code>4159974 fromspace 209664K, 4% used [0x00000006d9a80000, 0x00000006da36c210, 0x00000006e6740000)/<code>

  15. <code>4159975 to space 209664K, 0% used [0x00000006e6740000, 0x00000006e6740000, 0x00000006f3400000)/<code>

  16. <code>4159976 concurrent mark-sweep generation total 3354624K, used 141376K [0x00000006f3400000, 0x00000007c0000000, 0x00000007c0000000)/<code>

  17. <code>4159977 Metaspace used 128145K, capacity 136860K, committed 262144K, reserved 1234944K/<code>

  18. <code>4159978 classspace used 14443K, capacity 16168K, committed 77312K, reserved 1048576K/<code>

我這慧眼一瞧,看到了幾個關鍵單詞 <code>FullGC/<code>、<code>MetadataGCThreshold/<code>,然後很隨意的回覆了

是不是metaspace沒有設置,或者設置太小,導致的FGC

然後,又砸過來一段JVM參數配置

  1. <code>CATALINA_OPTS="$CATALINA_OPTS -server -Djava.awt.headless=true -Xms5324m -Xmx5324m -Xss512k -XX:PermSize=350m -XX:MaxPermSize=350m -XX:MetaspaceSize=256m -XX:MaxMet aspaceSize=256m -XX:NewSize=2048m -XX:MaxNewSize=2048m -XX:SurvivorRatio=8 -XX:MaxTenuringThreshold=9 -XX:+UseConcMarkSweepGC -XX:+UseCMSInitiatingOccupancyOnly -XX :+CMSScavengeBeforeRemark -XX:+ScavengeBeforeFullGC -XX:+UseCMSCompactAtFullCollection -XX:+CMSParallelRemarkEnabled -XX:CMSFullGCsBeforeCompaction=9 -XX:CMSInitiat ingOccupancyFraction=80 -XX:+CMSClassUnloadingEnabled -XX:SoftRefLRUPolicyMSPerMB=0 -XX:-ReduceInitialCardMarks -XX:+CMSPermGenSweepingEnabled -XX:CMSInitiatingPerm OccupancyFraction=80 -XX:+ExplicitGCInvokesConcurrent -Djava.nio.channels.spi.SelectorProvider=[sun.nio.ch](http://sun.nio.ch/).EPollSelectorProvider -Djava.util.logging.manager=org.apac he.juli.ClassLoaderLogManager -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -XX:+PrintHeapAtGC -Xloggc:/data/applogs/heap_trace.txt -XX:+IgnoreUnrecognizedVMOptions -XX:-HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/applogs/HeapDumpOnOutOfMemoryError"/<code>

“應該不是,我們配置了

-XX:MaxMetaspaceSize=256m

-XX:MetaspaceSize=256m”

看到配置之後,有點懵逼,好像超出了我的認知範圍,一下子沒回復,又扔過來一堆數據。

一次超诡异的FGC,你之前肯定没碰到过的场景,快Get起来

“看cat監控數據,Metaspace使用率在50%的時候就FGC了,GC 日誌上的顯示也只用了142M,可是我們明明設置了初始值是256M,最大值250M,這還沒達到閾值 ”

機智如我,趕緊回覆 “等等,我空的時候再看看 ”

一次超诡异的FGC,你之前肯定没碰到过的场景,快Get起来

等空閒下來,又想起了這個問題,決定好好研究下。

既然是Metadata GC Threshold引起的FGC,那麼只可能是MetadataSpace使用完了,我又反覆的看了下GC日誌片段,盯著看了會

  1. <code>[0x00000006f3400000, 0x00000007c0000000, 0x00000007c0000000)/<code>

  2. <code>4159977 Metaspace used 128145K, capacity 136860K, committed 262144K, reserved 1234944K/<code>

發生FGC之前,Metaspace的committed確實達到了256M,但是used卻只有125M,難道某一次的類初始化需要大於256 - 125 = 131M?

這顯然不合理,排除掉這種情況,那麼只有一種解釋了,Metaspace包含了太多了內存碎片,導致這256M中沒有足夠大的連續內存。

之前聽過老年代因為CMS的標記清理會產生內存碎片導致FGC,為什麼Metaspace也會有這樣的問題?

讓同事對有問題的機器dump了下,用mat打開之後,發現了新大陸,裡面包含了大量的類加載器。

難道這個碎片問題是大量類加載器引起的?

本地驗證

有了這個疑問,那就簡單了,看看能不能在本地復現。

1、先定義一個自定義的類加載器,破壞雙親委派

  1. <code>publicclassMyClassLoaderextendsClassLoader {/<code>


  2. <code>@Override/<code>

  3. <code>protectedClass> findClass(String name)throwsClassNotFoundException {/<code>

  4. <code>try{/<code>

  5. <code>String filePath = "/Users/zhanjun/Desktop/" + name.replace('.', File.separatorChar) + ".class";/<code>

  6. <code>//指定讀取磁盤上的某個文件夾下的.class文件:/<code>

  7. <code>File file = newFile(filePath);/<code>

  8. <code>FileInputStream fis = new

    FileInputStream(file);/<code>

  9. <code>byte bytes =newbyte[fis.available()];/<code>

  10. <code>fis.read(bytes);/<code>

  11. <code>//調用defineClass方法,將字節數組轉換成Class對象/<code>

  12. <code>Class> clazz = this.defineClass(name, bytes, 0, bytes.length);/<code>

  13. <code>fis.close;/<code>

  14. <code>returnclazz;/<code>

  15. <code>}catch(FileNotFoundException e){/<code>

  16. <code>e.printStackTrace;/<code>

  17. <code>}

    catch(IOException e) {/<code>

  18. <code>e.printStackTrace;/<code>

  19. <code>} finally{/<code>


  20. <code>}/<code>

  21. <code>returnsuper.findClass(name);/<code>

  22. <code>}/<code>

  23. <code>}/<code>

2、然後在while循環中,不斷的 load 已經編譯好的class文件

  1. <code>publicstaticvoidmain(String[] args)

    throwsException {/<code>

  2. <code>while(true) {/<code>

  3. <code>Class clazz0 = newMyClassLoader.loadClass("com.sankuai.discover.memory.OOM");/<code>

  4. <code>}/<code>

  5. <code>}/<code>

3、最後,配置一下jvm啟動參數

  1. <code>-Xmx2688M -Xms2688M -Xmn960M -XX:MetaspaceSize=50M -XX:MaxMetaspaceSize=100M -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -XX:+UseConcMarkSweepGC/<code>

啟動之後,不一會兒在控制檯果然出現了日誌

  1. <code>{Heap before GC invocations=0 (full 0):/<code>

  2. <code>par newgeneration total 884736K, used 330302K [0x0000000752400000, 0x000000078e400000, 0x000000078e400000)/<code>

  3. <code>eden space 786432K, 42% used [0x0000000752400000, 0x000000076668fae0, 0x0000000782400000)/<code>

  4. <code>fromspace 98304K, 0% used [0x0000000782400000, 0x0000000782400000, 0x0000000788400000)/<code>

  5. <code>to space 98304K, 0% used [0x0000000788400000, 0x0000000788400000, 0x000000078e400000)/<code>

  6. <code>concurrent mark-sweep generation total 1769472K, used 0K [0x000000078e400000, 0x00000007fa400000, 0x00000007fa400000)/<code>

  7. <code>Metaspace used 22636K, capacity 102360K, committed 102400K, reserved 1118208K/<code>

  8. <code>classspace used 8829K, capacity 33008K, committed 33008K, reserved 1048576K/<code>

  9. <code>2019-09-21T16:09:28.562-0800: [Full GC (Metadata GC Threshold) 2019-09-21T16:09:28.562-0800: [CMS: 0K->5029K(1769472K), 0.0987115 secs] 33030

    2K->5029K(2654208K), [Metaspace: 22636K->22636K(1118208K)], 0.1340367 secs] [Times: user=0.11 sys=0.03, real=0.13 secs] /<code>

  10. <code>Heap after GC invocations=1 (full 1):/<code>

  11. <code>par newgeneration total 884736K, used 0K [0x0000000752400000, 0x000000078e400000, 0x000000078e400000)/<code>

  12. <code>eden space 786432K, 0% used [0x0000000752400000, 0x0000000752400000, 0x0000000782400000)/<code>

  13. <code>fromspace 98304K, 0% used [0x0000000782400000, 0x0000000782400000, 0x0000000788400000)/<code>

  14. <code>to space 98304K, 0% used [0x0000000788400000, 0x0000000788400000, 0x000000078e400000)/<code>

  15. <code>concurrent mark-sweep generation total 1769472K, used 5029K [0x000000078e400000, 0x00000007fa400000, 0x00000007fa400000)/<code>

  16. <code>Metaspace used 2885K, capacity 4500K, committed 43008K, reserved 1058816K/<code>

  17. <code>classspace used 291K, capacity 388K, committed 33008K, reserved 1048576K/<code>

  18. <code>}/<code>

從日誌可以看出來,發生FGC之前,used大概22M,committed已經達到100M,這時再加載class的時候,需要申請內存,就不夠了,只能通過FGC對Metaspace的內存進行整理壓縮。

到現在,我們已經驗證了過多的類加載器確實可以引起FGC。

碎片是怎麼產生的?

其實,JVM內部為了實現高效分配,在類加載器第一次加載類的時候,會在Metaspace分配一個獨立的內存塊,隨後該類加載加載的類信息都保存在該內存塊。但如果這個類加載器只加載了一個類或者少數類,那這塊內存就被浪費了,如果類加載器又特別多,那內存碎片就產生了。

一次超诡异的FGC,你之前肯定没碰到过的场景,快Get起来


分享到:


相關文章: