前言

最近線上環(huán)境的CMS服務(wù)出現(xiàn)內(nèi)存增長非常快的情況，上午內(nèi)存2.4G下午就到了4G以上并且內(nèi)存的增長隨著時(shí)間推移一直增長，直到達(dá)到內(nèi)存空間限制然后pod重啟。由于之前沒有接觸過所以這次排查完記錄一下，主要是分享一下排查的思路和工具以及一些指令等。

這次問題的排查思路是先查看gc日志，通過gc日志分析內(nèi)存升高的過程主要是發(fā)生在哪個(gè)區(qū)，如果是堆外內(nèi)存那可能不大好排查，可以查看代碼中哪些涉及到大文件、大的字符串處理等，如果是新生代gc頻繁那就是臨時(shí)對象較多，gc日志只是做個(gè)大概的定位；其次主要還是需要對堆棧信息作分析，使用dump命令做快照，分別在服務(wù)剛啟動時(shí)和內(nèi)存飆升后做快照，對比升高后哪些對象的數(shù)量和大小增加。

GC日志

GC日志開啟

在啟動 Java 應(yīng)用程序時(shí)，通過 JVM 參數(shù)啟用 GC 日志記錄

JDK 8 及以下版本

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/path/to/gc.log

• -XX:+PrintGCDetails：打印 GC 的詳細(xì)信息。
• -XX:+PrintGCDateStamps：在日志中記錄 GC 的時(shí)間戳。
• -Xloggc:<file>：指定日志文件的位置。

JDK 9 及以上版本

-Xlog:gc*:file=/path/to/gc.log:time,uptime,level,tags

• gc*：記錄所有 GC 相關(guān)的日志。
• file=/path/to/gc.log：將日志輸出到指定文件。
• time,uptime,level,tags：控制日志格式。

查看GC日志

下面是線上的部分gc日志，從GC的間隔時(shí)間60、90、115可以看出頻率較高，表明應(yīng)用程序內(nèi)存分配壓力較大，同時(shí)新生代 GC 耗時(shí)從 0.127秒 增加到 0.715秒

2024-12-18T06:44:01.909+0000: 84819.612: [GC (Allocation Failure) 2024-12-18T06:44:01.910+0000: 84819.614: [DefNew: 1151910K->52843K(1230656K), 0.1256773 secs] 3431287K->2333097K(3965440K), 0.1275887 secs] [Times: user=0.13 sys=0.00, real=0.13 secs] 
2024-12-18T06:45:01.366+0000: 84879.070: [GC (Allocation Failure) 2024-12-18T06:45:01.368+0000: 84879.071: [DefNew: 1143848K->77773K(1230656K), 0.1896575 secs] 3424102K->2362281K(3965440K), 0.1915247 secs] [Times: user=0.18 sys=0.01, real=0.20 secs] 
2024-12-18T06:46:31.906+0000: 84969.609: [GC (Allocation Failure) 2024-12-18T06:46:31.907+0000: 84969.610: [DefNew: 1171725K->67117K(1230656K), 0.1596144 secs] 3456233K->2362116K(3965440K), 0.1615306 secs] [Times: user=0.15 sys=0.01, real=0.16 secs] 
2024-12-18T06:48:27.092+0000: 85084.795: [GC (Allocation Failure) 2024-12-18T06:48:27.093+0000: 85084.797: [DefNew: 1161069K->136703K(1230656K), 0.2665425 secs] 3456068K->2466626K(3965440K), 0.2688204 secs] [Times: user=0.24 sys=0.03, real=0.27 secs] 
2024-12-18T06:48:28.749+0000: 85086.452: [GC (Allocation Failure) 2024-12-18T06:48:28.751+0000: 85086.454: [DefNew: 1230655K->136704K(1230656K), 0.7121741 secs] 3560578K->2689414K(3965440K), 0.7152341 secs] [Times: user=0.38 sys=0.33, real=0.72 secs] 

時(shí)間戳：

• 2024-12-18T06:44:01.909+0000：GC 觸發(fā)的時(shí)間。
• 84819.612：JVM 啟動后的相對時(shí)間（秒）。

GC 觸發(fā)原因：

• (Allocation Failure)：因?yàn)闊o法為新對象分配空間觸發(fā) GC。

GC 類型：

• [DefNew]：使用 Serial GC，這是年輕代的 GC 類型（DefNew 表示新生代 GC）。

內(nèi)存變化：

1151910K->52843K(1230656K)

• 新生代從 1151910KB 降到 52843KB，容量上限為 1230656KB。
• 新生代的回收效果較明顯。

3431287K->2333097K(3965440K)

• 堆內(nèi)存從 3431287KB 降到 2333097KB，總堆內(nèi)存上限為 3965440KB。

耗時(shí)：

• 0.1275887 secs：GC 總耗時(shí) 127ms。

user=0.13 ser=0.13 sys=0.00, real=0.13 secs

• user：用戶線程執(zhí)行 GC 的 CPU 時(shí)間。
• sys：內(nèi)核線程執(zhí)行 GC 的 CPU 時(shí)間。
• real：實(shí)際經(jīng)過的時(shí)間。

堆?？煺?/h2>

直接查看高內(nèi)存時(shí)的內(nèi)存快照可能無法定位導(dǎo)致高內(nèi)存占用的對象，可以在項(xiàng)目剛啟動時(shí)和內(nèi)存占用很高時(shí)分別記錄快照，再使用內(nèi)存分析工具對比，可以比較直觀的看到導(dǎo)致內(nèi)存升高的對象，從而在項(xiàng)目里面快速定位。

生成快照

如果命令成功運(yùn)行，會在 /tmp 目錄下生成名為 heapdump.hprof 的文件，大小跟實(shí)際占用的內(nèi)存差不多，在做導(dǎo)出前可以使用壓縮指令壓縮提高傳輸效率

# 查看pid
ps -ef | grep java
# 生成內(nèi)存快照到指定目錄下
jmap -dump:format=b,file=/tmp/heapdump.hprof <pid>
# 壓縮
tar -czvf /tmp/heapdump.tar.gz /tmp/heapdump.hprof
# 解壓
tar -xzvf /tmp/heapdump.tar.gz

jmap：Java 內(nèi)存映射工具，用于生成堆轉(zhuǎn)儲或打印內(nèi)存統(tǒng)計(jì)信息。

• -dump：指定生成堆轉(zhuǎn)儲。
• format=b：轉(zhuǎn)儲文件的格式為二進(jìn)制（默認(rèn)格式）。
• file=/tmp/heapdump.hprof：堆轉(zhuǎn)儲文件保存的路徑。
• <pid>：目標(biāo) JVM 進(jìn)程的進(jìn)程 ID，可以通過 jps 或操作系統(tǒng)工具如 ps 查找。

得到的文件轉(zhuǎn)出到本地后解壓

IDEA中打開

2024.IntelliJ IDEA 2024.1.3 jprofiler

Run > Open Profiler Snapshot > Open再選擇文件即可打開快照文件

jprofiler的使用

下面是打開的效果圖，圖片下面是解釋分析內(nèi)存界面中的欄目字段含義。

1. Count

• 含義：表示特定類型的對象的實(shí)例數(shù)量。例如，某個(gè)類 com.example.MyClass 的對象在堆中有多少個(gè)實(shí)例。

2. Shallow

• 含義：Shallow Size（淺表大小），指某個(gè)對象本身占用的內(nèi)存大小，不包括它引用的其他對象。
• 單位：字節(jié)（Bytes）。
• 注意：例如，一個(gè)對象引用了其他對象，但 Shallow Size 只包括這個(gè)對象自身的內(nèi)存（如類頭和它的基本字段所占的內(nèi)存）。

3. Retained

• 含義：Retained Size（保留大?。?，表示某個(gè)對象被回收后可以釋放的總內(nèi)存，包括該對象本身和它所有可達(dá)的對象。
• 單位：字節(jié)（Bytes）。
• 重要性：Retained Size 是排查內(nèi)存泄漏的重要指標(biāo)。如果某個(gè)對象的 Retained Size 很大，說明它可能是根源問題。

4. Biggest Objects

• 含義：列出占用內(nèi)存最大的對象，通常根據(jù) Retained Size 排序。
• 作用：幫助快速找到哪些對象占用了最多的內(nèi)存，可能是內(nèi)存泄漏或不合理使用的根源。

5. GC Roots

• 含義：GC Roots（垃圾回收根）是指那些始終可達(dá)的對象，它們是垃圾回收的起點(diǎn)。
• 典型 GC Roots
• Java 棧中的局部變量。
• 靜態(tài)變量（類加載器持有）。
• JNI 引用的對象。
• 線程對象。
• 用途：通過分析對象如何從 GC Roots 保持引用，可以找出內(nèi)存泄漏的路徑。

6. Merged Paths

• 含義：在內(nèi)存分析中，工具會嘗試合并多條路徑，以簡化視圖并顯示引用鏈的關(guān)鍵部分。
• 作用：方便查看某個(gè)對象如何被其他對象引用和保留。

7. Summary

• 含義：一個(gè)總覽頁面，匯總堆中的信息，例如總對象數(shù)、內(nèi)存使用量、各類對象的分布等。
• 作用：快速獲取堆的整體狀況。

8. Packages

• 含義：顯示對象所屬的包（Package），并按包進(jìn)行分組統(tǒng)計(jì)。
• 用途：便于按模塊分析內(nèi)存使用情況，找出可能存在問題的模塊或包。

? 內(nèi)容太多總結(jié)一下分析時(shí)比較重要的：

• 可以重點(diǎn)關(guān)注Shollow欄并且根據(jù)他排序，它代表快照時(shí)在內(nèi)存中這個(gè)對象占用的大小，而它后面一欄Retained代表的是這個(gè)對象被回收的大小也具有很高的參考意義當(dāng)然需要結(jié)合Shollow如果只是被回收的多但是占用的不多那應(yīng)該也是問題不大，Shallow和Retained欄兩個(gè)都高的需要重點(diǎn)關(guān)注。
• 其次Merged Paths欄在問題分析中也非常重要，可以在選中左側(cè)的類之后分析這個(gè)類的來源以及引用鏈；Summary是線程的狀態(tài)信息，我這邊大部分是netty中的一些阻塞線程沒什么很明顯的問題；Packages是用來分析不同包下內(nèi)存占用情況的，我這里lang包占了1.28G實(shí)際上是不正常的但我分析的時(shí)候沒有經(jīng)驗(yàn)也沒有引起重視。

分析Shollow欄下切到 Merged Paths

先選中最大的對象，找到數(shù)量最多的類打開，查看Object[]的來源，最終指向的都是nacos下PoolThreadCache對象，并且有一個(gè)很反常的現(xiàn)象就是對象的回收java.lang.ref.Finalizer層級非常深根本點(diǎn)不完一直點(diǎn)一直有，并且對比啟動時(shí)的該對象內(nèi)存情況升高十分明顯，并且右側(cè)這個(gè)類的數(shù)量也是十分的高；

除此之外在對比時(shí)發(fā)現(xiàn)com.mysql.cj.jdbc.CallableStatement對象增長也十分明顯，它是在sql查詢時(shí)創(chuàng)建的查詢對象，理論上來說它也應(yīng)該在查詢完之后進(jìn)行銷毀，但實(shí)際上卻沒有被回收，不過這個(gè)對象被回收的數(shù)量也比較多又100多M，jdbc涉及到的配置也有限制，但限制外的預(yù)編譯對象沒有被回收，這個(gè)可能也有問題不過這次優(yōu)化中沒有處理內(nèi)存持續(xù)升高是其他問題造成，它的影響不是很大

# 是否開啟預(yù)編譯語句（PreparedStatement）的池化
db.master.poolPreparedStatements=true
# 每個(gè)數(shù)據(jù)庫連接可以緩存的 PreparedStatement 對象的最大數(shù)量
db.master.maxPoolPreparedStatementPerConnectionSize=10

Retained欄下切到 Merged Paths

切換過去之后問題就很明顯，回收對象大小排在前面的都是nacos相關(guān)的類，并且內(nèi)部都是java.lang.ref.Finalizer對象，層級非常深。

java.lang.ref.Finalizer實(shí)際是一個(gè)對象在創(chuàng)建時(shí)都會被一個(gè)特殊的 Finalizer 對象所追蹤，當(dāng)一個(gè)對象即將被垃圾回收器（GC）回收時(shí)，Finalizer 會將該對象標(biāo)記為可終結(jié)的對象，并調(diào)用其 finalize() 方法，主要作用就是清理資源和對象回收前的通知機(jī)制，finalize() 方法可以用于清理非 Java 堆中的資源，例如關(guān)閉文件流、Socket、釋放內(nèi)存等，不過但現(xiàn)代開發(fā)中，不建議依賴 finalize() 來做資源清理，因?yàn)樗膱?zhí)行時(shí)間和順序不可控，它只是通知或者是建議GC來干活需要進(jìn)行垃圾回收，但實(shí)際上是否進(jìn)行垃圾回收由JVM 和垃圾回收器控制，同時(shí)它也可以讓對象在完全銷毀之前執(zhí)行一些邏輯，例如記錄日志或釋放資源。

到這里初步定位于nacos的使用相關(guān)，網(wǎng)上查了一下對于java.lang.ref.Finalizer嵌套較深的原因是：Finalizer線程會和主線程進(jìn)行競爭，不過由于它的優(yōu)先級較低，獲取到的CPU時(shí)間較少，因此它永遠(yuǎn)也趕不上主線程的步伐?？梢詤⒖歼@篇文章Java的Finalizer引發(fā)的內(nèi)存溢出，仔細(xì)一想其實(shí)是句廢話說白了就是回收垃圾的速度趕不上制造垃圾的速度，實(shí)際結(jié)果肯定是這樣不然也不會有內(nèi)存持續(xù)升高最終溢出的結(jié)果，除此之外github上也有帖子nacos客戶端2.0.1 PoolThreadCache 內(nèi)存溢出，說是nacos某些版本的bug并且該問題沒有給出解決方案就被關(guān)閉了。

由于是nacos相關(guān)的問題，所以直接在項(xiàng)目中搜索"nacos."，看哪些類有使用nacos相關(guān)的類，結(jié)果只有健康檢查類里面有相關(guān)使用，下面是用到的部分代碼，主要邏輯就是獲取nacos中所有可用的服務(wù)，請求服務(wù)的某個(gè)接口如果返回?cái)?shù)據(jù)就代表服務(wù)健康狀態(tài)。

public void checkServiceHealth() throws NacosException {
        SysLogger.info(this.getClass(),"健康檢查進(jìn)入：");
        NamingService namingService = NamingFactory.createNamingService(serverList);
        // 獲取所有服務(wù)的列表
        List<String> serviceNames = namingService.getServicesOfServer(1, Integer.MAX_VALUE).getData();
        // 遍歷所有服務(wù)
        for (String serviceName : serviceNames) {
            // 獲取指定服務(wù)的所有實(shí)例
            List<Instance> instances = namingService.getAllInstances(serviceName);
            // 遍歷服務(wù)的實(shí)例
            for (Instance instance : instances) {
              	//......
                // 模擬http請求向服務(wù)發(fā)送健康檢查接口
              ResponseEntity<String> response = restTemplate.getForEntity(serverIp, String.class)
            }
        }
    }

問題就出在代碼

NamingService namingService = NamingFactory.createNamingService(serverList)

下面是這個(gè)方法的內(nèi)部代碼，通過反射去創(chuàng)建NamingService對象，說明對象并不是單例的每次都會創(chuàng)建一個(gè)新對象，而這個(gè)方法由于是健康檢查使用幾分鐘就執(zhí)行一次，時(shí)間一長對象就會非常多。盡管這個(gè)對象會創(chuàng)建很多但是理論上還是會被垃圾回收器回收掉對內(nèi)存的影響可能也不會很大，但是問題的關(guān)鍵就在于模擬http請求時(shí)的

ResponseEntity<String> response = restTemplate.getForEntity(serverIp, String.class);

RestTemplate 默認(rèn)使用的是 HTTP Keep-Alive 機(jī)制，這是一種復(fù)用底層 TCP 連接的機(jī)制，可以提升 HTTP 請求的性能并減少資源消耗，但如果跟非單例對象一起可能導(dǎo)致NamingService形成強(qiáng)引用無法被回收。

public static NamingService createNamingService(String serverList) throws NacosException {
        try {
            Class<?> driverImplClass = Class.forName("com.alibaba.nacos.client.naming.NacosNamingService");
            Constructor constructor = driverImplClass.getConstructor(String.class);
            NamingService vendorImpl = (NamingService)constructor.newInstance(serverList);
            return vendorImpl;
        } catch (Throwable var4) {
            Throwable e = var4;
            throw new NacosException(-400, e);
        }
    }

解決

知道了原因修改的話就很簡單了，把NamingService的獲取方式變成單例就可以了

    @Autowired
    private NamingService namingService;

    // 獲取所有服務(wù)的列表
    List<String> serviceNames = namingService.getServicesOfServer(1, Integer.MAX_VALUE).getData();

總結(jié)

修改之后上線觀察cms的內(nèi)存占用情況改善非常明顯，由原來的4個(gè)多G變成現(xiàn)在的2G左右，并且穩(wěn)定在2G左右基本不會升高。本次解決的問題只有NamingService對象較多無法回收的問題，但實(shí)際上在分析的過程中也發(fā)現(xiàn)了在運(yùn)行的過程中com.mysql.cj.jdbc.CallableStatement對象增上也十分迅速，由2G內(nèi)存時(shí)的20w增長到4.2G內(nèi)存時(shí)的90w，這個(gè)問題并沒有在這次優(yōu)化中處理，后面這個(gè)對象肯定會隨著時(shí)間的推移數(shù)量變的越來越多，并且這個(gè)對象也不會被垃圾回收器回收，所以可能后面還需要處理這個(gè)問題。

本次線上問題的定位與解決都是我同事，在此僅僅是做個(gè)記錄，我在做分析時(shí)我看到了那個(gè)引用鏈非常長的問題，但是并沒有引起我的注意，因?yàn)槲乙豢催@個(gè)是nacos的類所以不會有問題如果我們的項(xiàng)目有問題那類似用了nacos的是不是都會有問題，所以直接忽略了在其他地方浪費(fèi)了很多時(shí)間，我想說的是在分析問題時(shí)還需要耐心的分析不忽略任何可能的點(diǎn)，定位問題時(shí)不能先入為主，想當(dāng)然的認(rèn)為某個(gè)地方肯定沒有問題，因?yàn)檫@樣很有可能會漏掉最重要的點(diǎn)，同時(shí)告誡自己做事多一些耐心、細(xì)心。

以上為個(gè)人經(jīng)驗(yàn)，希望能給大家一個(gè)參考，也希望大家多多支持腳本之家。

最新評論