碼上快樂

相關內容    簡體    繁體

20.GC日志詳解及日志分析工具

本文轉載自   查看原文   2022-01-12 16:02   3238    JVM虛擬機

分析JVM性能，肯定要看GC日志，那么GC日志中各個參數都代表什么含義呢？祥看下文。
日志導出來以后，用肉眼看，太費勁了，來看看有什么好用的工具對GC日志進行分析。不管能分析，還有推薦解決方案哦。

一、GC日志

我們在打印日志的時候，增加下面的參數，可以打印更加詳細的日志

1. 日志命令解析

‐Xloggc:./gc‐%t.log ‐XX:+PrintGCDetails ‐XX:+PrintGCDateStamps ‐XX:+PrintGCTimeStamps ‐XX:+PrintGCCause ‐XX:+UseGCLogFileRotation ‐XX:NumberOfGCLogFiles=10 ‐XX:GCLogFileSize=100M
  • ‐Xloggc參數：指定gc日志的保存地址。這里指定的是當前目錄，文件名以gc-+時間戳.log打印。%t表示時間戳
  • ‐XX:+PrintGCDetails：在日志中打印GC詳情。
  • ‐XX:+PrintGCDateStamps：在日志中打印GC的時間
  • ‐XX:+PrintGCTimeStamps：在日志中打印GC耗時
  • ‐XX:+PrintGCCause ： [這個參數沒查到]
  • ‐XX:+UseGCLogFileRotation：這個參數表示以滾動文件的形式打印日志
  • ‐XX:NumberOfGCLogFiles：GC日志文件的最大個數，這里設置10個
  • ‐XX:GCLogFileSize：GC日志每個文件的最大容量，這里是100M

2. 日志內容解析

1) 新生代YoungGen內存分配失敗觸發Minor GC--日志解析

2022-01-11T17:51:35.992-0800: 47.713: [GC (Allocation Failure) [PSYoungGen: 1280509K->89599K(1308160K)] 1396384K->217194K(1509376K), 0.0251936 secs] [Times: user=0.08 sys=0.01, real=0.02 secs]
  • 2022-01-11T17:51:35.992-0800：能夠打印這個時間是因為設置了‐XX:+PrintGCDateStamps參數。打印日志輸出的時間
  • 47.713：從jvm啟動直到垃圾收集發生所經歷的時間。這個時間是因為設置了‐XX:+PrintGCTimeStamps參數
  • GC：表示這是一次Minor GC（新生代垃圾收集）；
  • (Allocation Failure)：觸發GC的原因是，給Young Gen內存分配失敗導致的
  • [PSYoungGen: 1280509K->89599K(1308160K)] 提供了新生代空間的信息，
    • PSYoungGen，表示新生代使用的是多線程垃圾收集器Parallel Scavenge。
    • 1280509K表示垃圾收集之前新生代占用空間，
    • 89599K表示垃圾收集之后新生代的空間。
    • 括號里的1308160K表示整個年輕代的大小。
    • 新生代又細分為一個Eden區和兩個Survivor區, Minor GC之后Eden區為空，6577K就是Survivor占用的空間。
  • 1396384K->217194K(1509376K)
    • 1396384K：表示垃圾收集之前Java堆占用的大小
    • 217194K：表示垃圾收集之后Java堆占用的大小
    • 1509376K：總堆大小1509376K，包括新生代和年老代
  • 0.0251936 secs：表示垃圾收集過程所消耗的時間。
  • [Times: user=0.08 sys=0.01, real=0.02 secs]：提供cpu使用及時間消耗
    • user是用戶模式垃圾收集消耗的cpu時間，實例中垃圾收集器消耗了0.08秒用戶態cpu時間
    • sys是消耗系統態cpu時間
    • real是指垃圾收集器消耗的實際時間
  • 由新生代和Java堆占用大小可以算出年老代占用空間，
    • Java堆空間總大小1509376K，新生代空間總大小1308160K，那么老年代空間總大小是1509376K-1308160K=201216K；
    • 垃圾收集之前老年代占用的空間為1396384K-1280509K=115875K
    • 垃圾收集之后老年代占用空間217194K-89599K=127595k.

2) 元數據（方法區）空間不足觸發Full GC--日志解析

2022-01-11T17:54:45.790-0800: 4.307: [Full GC (Metadata GC Threshold) [PSYoungGen: 12761K->0K(497664K)] [ParOldGen: 15911K->18963K(108032K)] 28672K->18963K(605696K), [Metaspace: 34603K->34603K(1081344K)], 0.0401502 secs] [Times: user=0.16 sys=0.00, real=0.04 secs]

fullGC 觸發的原因是：元空間（方法區）空間不足

3) 元數據（方法區）空間不足觸發MinofGC--日志解析

2022-01-11T17:54:45.782-0800: 4.299: [GC (Metadata GC Threshold) [PSYoungGen: 37195K->12761K(497664K)] 53098K->28672K(577536K), 0.0078608 secs] [Times: user=0.03 sys=0.01, real=0.01 secs]

Minor GC觸發的原因：元空間不足

4） 系統調用觸發GC--日志解析

系統調用觸發GC， JVM內部環境認為此時可以進行一次垃圾收集

2022-01-11T17:54:53.979-0800: 12.496: [Full GC (Ergonomics) [PSYoungGen: 49151K->0K(1077760K)] [ParOldGen: 91750K->95410K(221184K)] 140902K->95410K(1298944K), [Metaspace: 53259K->53259K(1097728K)], 0.1806514 secs] [Times: user=0.96 sys=0.01, real=0.19 secs]

二、實戰：項目啟動時速度很慢

我們來觀察一下，當項目啟動的時候，啟動耗時特別長，這時可以打印GC日志看一下。

image

2022-01-12T11:05:59.658-0800: 1.334: [GC (Allocation Failure) [PSYoungGen: 65536K->4358K(76288K)] 65536K->4374K(251392K), 0.0196609 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 

2022-01-12T11:06:00.062-0800: 1.738: [GC (Allocation Failure) [PSYoungGen: 69894K->5059K(141824K)] 69910K->5147K(316928K), 0.0060396 secs] [Times: user=0.02 sys=0.01, real=0.00 secs] 

2022-01-12 11:06:00,193 main ERROR Console contains an invalid element or attribute "append"
  
2022-01-12T11:06:00.886-0800: 2.561: [GC (Allocation Failure) [PSYoungGen: 136131K->10741K(141824K)] 136219K->11359K(316928K), 0.0159439 secs] [Times: user=0.03 sys=0.01, real=0.02 secs] 

2022-01-12T11:06:00.958-0800: 2.634: [GC (Metadata GC Threshold) [PSYoungGen: 23884K->7144K(272896K)] 24502K->7771K(448000K), 0.0063136 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 

2022-01-12T11:06:00.965-0800: 2.640: [Full GC (Metadata GC Threshold) [PSYoungGen: 7144K->0K(272896K)] [ParOldGen: 626K->7038K(88576K)] 7771K->7038K(361472K), [Metaspace: 20521K->20520K(1067008K)], 0.0280148 secs] [Times: user=0.10 sys=0.01, real=0.03 secs]

當項目啟動1.3s的時候，便開始觸發Minor GC了。因為項目剛剛啟動的時候，要加載很多類，隨后2.640的時候便觸發了一次Full GC，觸發的原因是元數據空間不足導致。元數據空間[Metaspace: 20521K->20520K(1067008K)]消耗了20M了，垃圾回收之后，元數據空間基本上沒有被回收，因為元數據空間保存的是類信息。我們知道元數據默認空間大小是21M，如果空間不足會觸發Full GC，然后擴容。

2022-01-12T11:06:04.538-0800: 6.214: [Full GC (Metadata GC Threshold) [PSYoungGen: 11694K->0K(466944K)] [ParOldGen: 13317K->17995K(115200K)] 25011K->17995K(582144K), [Metaspace: 34079K->34079K(1079296K)], 0.0563024 secs] [Times: user=0.15 sys=0.00, real=0.06 secs]

在項目啟動的第6s，再次觸發了Full GC，原因也是元數據空間不足導致。這次元數據空間[Metaspace: 34079K->34079K(1079296K)]消耗了34M，垃圾回收完畢以后，也是基本沒被回收。但是我們可以看出，元數據空間擴容了，從21M擴到了34M.

所以，如果項目啟動的時候要加載的類很多，元數據空間就會不斷的擴容，本身這個擴容的過程就是很耗時的。

為了避免這個情況，我們可以在項目啟動的時候提前設置好元數據空間的大小，避免其頻繁的擴容.

 ‐XX:MetaspaceSize=256M ‐XX:MaxMetaspaceSize=256M

我們重新配置參數，啟動項目，看看效果, 發現，Full GC少了。

1  ‐Xloggc:./gc‐adjust‐%t.log -XX:MetaspaceSize=256M -XX:MaxMetaspaceSize=256M ‐XX:+PrintGCDetails -XX:+Print GCDateStamps -XX:+PrintGCTimeStamps ‐XX:+PrintGCCause ‐XX:+UseGCLogFileRotation ‐XX:NumberOfGCLogFiles=10 ‐XX:GCLogFileSize=100M

三、日志分析工具

我們看到日志，尤其是CMS和G1的日志，直接看日志文檔都是很不方便的，密密麻麻的文字，其實市面上已經有一些日志分析工具了。今天我們就來給大家介紹一款：gceasy.io

網址：https://gceasy.io/

這款工具不需要我們下載軟件，他是在線的。我們要做的就是兩步：

步驟一：導出GC日志到本地磁盤

步驟二：將本地日志上傳到gceasy.io上，進行分析

下面我們來具體實戰一下：

第一步：導出日志

-Xloggc:/Users/lxl/Downloads/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCCause
  • ‐Xloggc參數：指定gc日志的保存地址。這里指定的是當前目錄，文件名以gc-+時間戳.log打印。%t表示時間戳
  • ‐XX:+PrintGCDetails：在日志中打印GC詳情。
  • ‐XX:+PrintGCDateStamps：在日志中打印GC的時間
  • ‐XX:+PrintGCTimeStamps：在日志中打印GC耗時
  • ‐XX:+PrintGCCause ： [這個參數沒查到]
  • ‐XX:+UseGCLogFileRotation：這個參數表示以滾動文件的形式打印日志
  • ‐XX:NumberOfGCLogFiles：GC日志文件的最大個數，這里設置10個
  • ‐XX:GCLogFileSize：GC日志每個文件的最大容量，這里是100M

我們把日志下載到Downloads文件夾下了。以下便是GC日志的全部內容

Java HotSpot(TM) 64-Bit Server VM (25.202-b08) for bsd-amd64 JRE (1.8.0_202-b08), built on Dec 15 2018 20:16:16 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
Memory: 4k page, physical 16777216k(1745536k free)

/proc/meminfo:

CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:InitialHeapSize=268435456 -XX:+ManagementServer -XX:MaxHeapSize=4294967296 -XX:+PrintGC -XX:+PrintGCCause -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
2022-01-12T15:02:37.044-0800: 0.839: [GC (Allocation Failure) [PSYoungGen: 65536K->4400K(76288K)] 65536K->4416K(251392K), 0.0043915 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2022-01-12T15:02:37.308-0800: 1.103: [GC (Allocation Failure) [PSYoungGen: 69936K->4959K(76288K)] 69952K->5047K(251392K), 0.0046449 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] 
2022-01-12T15:02:37.625-0800: 1.420: [GC (Allocation Failure) [PSYoungGen: 70495K->7467K(76288K)] 70583K->7563K(251392K), 0.0051392 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2022-01-12T15:02:37.831-0800: 1.627: [GC (Allocation Failure) [PSYoungGen: 73003K->9356K(141824K)] 73099K->9460K(316928K), 0.0072596 secs] [Times: user=0.03 sys=0.01, real=0.00 secs] 
2022-01-12T15:02:37.869-0800: 1.664: [GC (Metadata GC Threshold) [PSYoungGen: 22322K->7049K(141824K)] 22426K->7161K(316928K), 0.0057809 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2022-01-12T15:02:37.875-0800: 1.670: [Full GC (Metadata GC Threshold) [PSYoungGen: 7049K->0K(141824K)] [ParOldGen: 112K->6873K(87040K)] 7161K->6873K(228864K), [Metaspace: 20573K->20571K(1067008K)], 0.0237404 secs] [Times: user=0.09 sys=0.01, real=0.02 secs] 
2022-01-12T15:02:38.392-0800: 2.188: [GC (Allocation Failure) [PSYoungGen: 131072K->7194K(236032K)] 137945K->14075K(323072K), 0.0054542 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] 
2022-01-12T15:02:39.850-0800: 3.646: [GC (Allocation Failure) [PSYoungGen: 235546K->9697K(270336K)] 242427K->20203K(357376K), 0.0092838 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] 
2022-01-12T15:02:40.479-0800: 4.274: [GC (Metadata GC Threshold) [PSYoungGen: 179780K->12779K(397312K)] 190286K->25839K(484352K), 0.0117953 secs] [Times: user=0.04 sys=0.01, real=0.02 secs] 
2022-01-12T15:02:40.491-0800: 4.286: [Full GC (Metadata GC Threshold) [PSYoungGen: 12779K->0K(397312K)] [ParOldGen: 13059K->21448K(132096K)] 25839K->21448K(529408K), [Metaspace: 34068K->34068K(1079296K)], 0.0437361 secs] [Times: user=0.16 sys=0.01, real=0.04 secs] 
2022-01-12T15:02:42.177-0800: 5.972: [GC (Allocation Failure) [PSYoungGen: 384512K->13185K(399872K)] 405960K->34641K(531968K), 0.0115070 secs] [Times: user=0.04 sys=0.01, real=0.01 secs] 
2022-01-12T15:02:43.010-0800: 6.806: [GC (Allocation Failure) [PSYoungGen: 397697K->16864K(530432K)] 419153K->58461K(662528K), 0.0248406 secs] [Times: user=0.04 sys=0.02, real=0.02 secs] 
2022-01-12T15:02:44.338-0800: 8.133: [GC (Allocation Failure) [PSYoungGen: 530400K->26083K(539648K)] 571997K->86488K(671744K), 0.0302789 secs] [Times: user=0.06 sys=0.02, real=0.03 secs] 
2022-01-12T15:02:45.800-0800: 9.595: [GC (Allocation Failure) [PSYoungGen: 539619K->32647K(733696K)] 600024K->99769K(865792K), 0.0280332 secs] [Times: user=0.04 sys=0.02, real=0.02 secs] 
2022-01-12T15:02:47.765-0800: 11.560: [GC (Allocation Failure) [PSYoungGen: 729479K->41445K(738304K)] 796601K->124936K(870400K), 0.0370655 secs] [Times: user=0.04 sys=0.02, real=0.04 secs] 
2022-01-12T15:02:49.620-0800: 13.415: [GC (Allocation Failure) [PSYoungGen: 738277K->26677K(974848K)] 821768K->114930K(1106944K), 0.0270382 secs] [Times: user=0.05 sys=0.02, real=0.02 secs] 
2022-01-12T15:02:52.146-0800: 15.942: [GC (Allocation Failure) [PSYoungGen: 959541K->17569K(985600K)] 1047794K->110447K(1117696K), 0.0274985 secs] [Times: user=0.05 sys=0.01, real=0.03 secs] 
2022-01-12T15:02:54.110-0800: 17.905: [GC (Allocation Failure) [PSYoungGen: 950433K->10240K(1236480K)] 1043311K->109662K(1368576K), 0.0146713 secs] [Times: user=0.05 sys=0.01, real=0.01 secs] 
2022-01-12T15:02:54.692-0800: 18.487: [GC (Metadata GC Threshold) [PSYoungGen: 264005K->3360K(1259520K)] 363427K->109573K(1391616K), 0.0086901 secs] [Times: user=0.03 sys=0.01, real=0.01 secs] 
2022-01-12T15:02:54.701-0800: 18.496: [Full GC (Metadata GC Threshold) [PSYoungGen: 3360K->0K(1259520K)] [ParOldGen: 106213K->54092K(208384K)] 109573K->54092K(1467904K), [Metaspace: 56204K->56204K(1101824K)], 0.1487173 secs] [Times: user=0.69 sys=0.01, real=0.14 secs] 
2022-01-12T15:02:57.787-0800: 21.583: [GC (Allocation Failure) [PSYoungGen: 1209856K->49146K(1321984K)] 1263948K->116260K(1530368K), 0.0339265 secs] [Times: user=0.05 sys=0.01, real=0.04 secs] 
2022-01-12T15:03:16.198-0800: 39.994: [GC (Allocation Failure) [PSYoungGen: 1321978K->29589K(1335296K)] 1389092K->101049K(1543680K), 0.0214759 secs] [Times: user=0.06 sys=0.01, real=0.03 secs] 
2022-01-12T15:03:19.021-0800: 42.816: [GC (GCLocker Initiated GC) [PSYoungGen: 1302421K->60915K(1280512K)] 1373881K->180735K(1488896K), 0.0482886 secs] [Times: user=0.08 sys=0.01, real=0.05 secs] 
2022-01-12T15:03:21.847-0800: 45.642: [GC (Allocation Failure) [PSYoungGen: 1280499K->89087K(1308672K)] 1400321K->228379K(1517056K), 0.0336500 secs] [Times: user=0.10 sys=0.01, real=0.04 secs] 
2022-01-12T15:03:24.516-0800: 48.311: [GC (Allocation Failure) [PSYoungGen: 1308671K->67295K(1257472K)] 1447963K->225652K(1465856K), 0.0381420 secs] [Times: user=0.07 sys=0.02, real=0.04 secs]

第二步：導入分析工具，盡心分析

打開gceasy.io網站，並選擇本地的gc文件，然后點擊分析。（分析的速度根據日志的多少而定，可能會比較慢）

image

接下來看看分析結果：

JVM memory size (JVM內存大小)

![image-20220112151703421](/Users/luoxiaoli/Library/Application Support/typora-user-images/image-20220112151703421.png)

這里的Allocated和Peak分別表示可分配空間和峰值

  • Allocated：可分配空間大小。具體含義如下：指示為每一代分配的大小。此數據點是從GC日志收集的，因此它可能與JVM系統屬性指定的大小相匹配，也可能不匹配。假設您已將總堆大小配置為2gb，而在運行時，如果JVM只分配了1gb，那么在本報告中，您將看到分配的大小僅為1gb

  • Peak： 分配的峰值。具體含義如下：每一代的峰值內存利用率。通常它不會超過分配的大小。然而，在少數情況下，我們也看到峰值利用率超出了分配的大小，特別是在G1 GC中

這里統計的是JVM內存空間的大小

  • 新生代：可分配空間是1.28g，峰值使用是1.28G
  • 老年代：可分配空間201M，峰值是150.63M
  • 元數據：可分配空間1.05G，峰值54M
  • 總計：5.05G，1.44G

Key Performance Indicatiors（關鍵指標）

image

  • Throughput：吞吐量。指的是處理實際事務花費的時間與GC花費的時間的百分比。這個值越高越好
  • Latency：延遲情況。這里的延遲情況是指的GC過程花費的時間。具體含義如上圖

Interactive Graphs

image

  • GC前后堆空間大小

GC統計

image

這里列出了Minor GC 的情況， Full GC的情況， GC停頓統計， 以及總的GC統計

Memory Leak

image

GC Causes

image

GC產生的原因分析

  • 內存分配失敗觸發GC的情況統計：
  • 元數據空間不足觸發GC的情況統計：
  • GCLocker啟動的GC觸發GC的情況統計 ：

重磅功能---GC分析后的優化

image

只可惜是收費的。據說找問題的准確率還是挺高的。


免責聲明！

本站轉載的文章為個人學習借鑒使用，本站對版權不負任何法律責任。如果侵犯了您的隱私權益，請聯系本站郵箱yoyou2525@163.com刪除。



猜您在找 GC之七--gc日志分析工具 GC日志分析詳解 JVM GC日志分析及Gc日志分析工具 GC之詳解CMS收集過程和日志分析 可視化GC日志分析工具 可視化GC日志分析工具 JVM優化GC日志分析-GC Easy工具 JVM關於GC的日志分析 GC日志時間分析 gc日志收集和分析
 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM