Spring Cloud之量化分析應用續租的記憶體消耗

歡迎通路陳同學 部落格原文 本文修改了三次，感謝 曉波同學 、 帆哥 提的問題、建議與知識幫助。

在分享

《Spring Cloud之極端續租間隔時間的影響》

後，曉波同學問：由于心跳頻率過高導緻出現新對象過多？

索性就試試 量化分析一次心跳帶來的記憶體消耗！本文純屬好奇心驅使，無實際意義。

如何量化分析？

量化分析？那麼多幹擾因素，怎麼個分析法？

測試中有黑盒、白盒測試，而JVM基本是個黑盒，隻能通過各性能采集工具或利用JVM自身産生的性能資料來分析。

想起初高中生物對照試驗中的 控制變量法，即各對照組中通常設定1各變量，其他條件保持一緻。

那就準備一個實驗組，一個對照組，先看看變量與影響因子。

變量

• 心跳頻率：第一組心跳頻率保持 1s/次，第二組心跳 10分鐘/次(在試驗期間内不進行心跳)

兩組試驗唯一不同的就是是否心跳，下面就盡量排除各種幹擾因素。

影響因素

• 測試的機器實時資源情況幹擾：同時運作兩組試驗，確定它們在相同環境下運作
• GC的影響：盡量在應用啟動穩定後(排除啟用時的頻繁GC)的第一次GC内完成試驗，同時Metaspace設定為500M，避免因Metaspace引發Full GC
• 租約失效時間：設定為10分鐘，確定第二組注冊到Eureka Server後不會被剔除
• Fetch registry的影響：将Eureka Client從Server擷取所有執行個體資訊的頻率設定為10分鐘，在試驗期間不要fetch registry
• 性能采集工具影響：采用jstat，jstat是讀取JVM寫在磁盤上的性能資料，對JVM沒什麼幹擾。

可參考笨神的 JVM源碼分析之Jstat工具原理完全解讀 ，JVM預設50ms寫一次性能資料到磁盤，需要采集資料的直接去擷取，可使用 jcmd pid PerfCounter.print來體驗下。VisualVM這種圖形化工具不友善統計資料。

• 其他個人認知水準外的未知因素

試驗環境

• JDK1.8
• Mac OS

希望通過以jstat指令持續列印Eden區記憶體的變化來采集資料，并結合其他日志作為資料來進行定量分析。

試驗準備

将簡單的Eureka Client應用打成jar包，以jar包形式同時運作2個應用。為了觀察心跳情況，2個應用心跳請求都經過本機nginx代理。

下面為試驗簡圖，兩個應用分别跑在8080、8081端口，請求經Nginx代理并轉發到Eureka Server。

Client1表示續租頻率1s/次，Client600表示續租頻率600s/次。

用

tail -f

檢視nginx日志，可以動态、清晰的觀察client1的續租請求。

動手做試驗

啟動應用

兩應用的預設配置：

# 排除fetch registry 任務的幹擾，僅應用啟動時擷取一次
eureka.client.registry-fetch-interval-seconds=600
# 租約有效時間為 10分鐘
eureka.instance.lease-expiration-duration-in-seconds=600           

以下列指令同時運作兩個應用，除續租間隔分别為1秒和600秒外，無任何差别。

nohup java -Dspring.application.name=eureka-client1 -Dserver.port=8080 -Deureka.instance.lease-renewal-interval-in-seconds=1 -Xmx100m -Xms100m -XX:NewRatio=1 -XX:MetaspaceSize=500m -verbosegc -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:/Users/cyj/test/gc-client1.log -jar eureka-client.jar &

nohup java -Dspring.application.name=eureka-client600 -Dserver.port=8081 -Deureka.instance.lease-renewal-interval-in-seconds=600 -Xmx100m -Xms100m -XX:NewRatio=1 -XX:MetaspaceSize=500m -verbosegc -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:/Users/cyj/test/gc-client600.log -jar eureka-client.jar &           

收集Nginx日志

日志中1-6序号是我标記的，僅截取了日志的關鍵屬性

1:"GET /eureka/apps/ HTTP/1.1" 200 80
2:"GET /eureka/apps/ HTTP/1.1" 200 80
3:"POST /eureka/apps/EUREKA-CLIENT1 HTTP/1.1" 204 0
4:"POST /eureka/apps/EUREKA-CLIENT600 HTTP/1.1" 204 0
5:"PUT /eureka/apps/EUREKA-CLIENT1/192.168.31.136:eureka-client1:8080?status=UP&lastDirtyTimestamp=1535551985958 HTTP/1.1" 200 0
6:"PUT /eureka/apps/EUREKA-CLIENT1/192.168.31.136:eureka-client1:8080?status=UP&lastDirtyTimestamp=1535551985958 HTTP/1.1" 200 0           

啟用應用後，

• 第1-2行是兩個應用fetch registry的請求
• 第3-4行

  POST

  請求是兩個應用首次注冊的請求
• 第5行開始，日志以每秒1次的頻率出現，是Client1的心跳

  PUT

  請求日志

此時，兩個應用已達到預期的運作狀态。

收集GC日志

在應用啟動後運作一段時間後，檢視GC日志(僅截取了啟動後的日志)。

client1的日志(序号由我标記，不是GC日志的一部分)：

...
1->6.881: [GC (Allocation Failure) 
2->7.152: [GC (Allocation Failure) 
3->7.493: [GC (Allocation Failure) 
4->7.623: [GC (Allocation Failure) 
5->435.604: [GC (Allocation Failure)           

在第4行時，應用啟動結束，耗時7.623秒。第5行為第一次GC發生的時間。

client600的日志

...
7.129: [GC (Allocation Failure)
7.392: [GC (Allocation Failure)
7.747: [GC (Allocation Failure)
7.903: [GC (Allocation Failure)           

在運作一段分鐘後，直到我stop應用，client600并未發生GC。

client600 啟動時間為 7.903 ，與client1的 7.623 并無太大差異，且GC啟動期間兩應用發生的GC次數一緻。

收集Eden區記憶體變化

使用 jstat -gc 1000，每秒列印一次

client1 的記憶體變化如下，僅列出中間部分。下面資料重新整理間隔為1秒。

EU 即Eden的使用量 以一定速度，非正常律的變化，其他名額并無變化。

EC       EU      YGC   YGCT     
...
  45056.0  4729.8  63  0.165
  45056.0  4729.8  63  0.165
  45056.0  4729.8  63  0.165
  45056.0  5056.0  63  0.165
  45056.0  5056.0  63  0.165
  45056.0  5056.0  63  0.165
  46080.0  1273.0  64  0.167
...           

再看看client600 的記憶體變化，僅列出中間部分。

整個試驗期間，Eden區隻有3次變化，從25993.8到26895.6。

EC       EU       YGC   YGCT      
...
45056.0  25993.8  63    0.169  
45056.0  25993.8  63    0.169  
45056.0  26895.6  63    0.169  
45056.0  26895.6  63    0.169  
45056.0  26895.6  63    0.169  
...
45056.0  26895.6  63    0.169  
45056.0  26895.6  63    0.169  
45056.0  26895.6  63    0.169  
...           

光這麼看看不出什麼，最後将基于兩個試驗組在相同時間内的Eden變化來分析資料。

收集threadstack情況

使用jstack收集試驗期間線程情況。

除應用運作的必要線程外，并無其他線程在運作。排查無關線程幹擾。

資料分析

主要分析jstat得到的資料。EC表示Eden區容量，EU表示Eden區使用量，機關為KB。

client1和client600的EC都是45056.0，在下面的試驗資料中未發生變化。

時間	client1 EU	client600 EU
開始	30583.0	25993.8(不變)
10s後	31200.1
20s後	31518.5
50s後	32738.6
104秒後	35174.1	26895.6
240秒後	41699.1	27797.1
316秒後	45056.0

以上為在應用啟動後約5分鐘的統計資料(還有很多，5分鐘的資料已夠分析了，317秒時client1發生了GC)， 統計開始時 client1 消耗的記憶體已比 client600 多。

下面開始分析資料：

• 試驗總耗時：316秒
• client1記憶體消耗：45056.0 - 30583.0 = 14473(14.47M)
• client600記憶體消耗：27797.1 - 25993.8 = 1803.3(1.8M)

由于client600未進行續租，可以認為 它的記憶體消耗是應用正常運作的必要消耗。

那client1的心跳消耗可認為是：client1記憶體消耗(14473) - client600記憶體消耗(1803.3)，值為：12669.7

每次心跳消耗的記憶體＝心跳記憶體消耗 ÷ 心跳耗時。

雖然client向server發送請求也會消耗時間，但由于是本機通訊，我們暫且忽略這個極小的時間消耗。認為316秒發生了316次心跳。

下面是nginx部分日志，由于在容器中運作，時間未進行校準。且日志忘了把毫秒列印出來，先忽略這個時間消耗。

[29/Aug/2018:14:13:11 +0000] "PUT /eureka/apps/EUREKA-CLIENT1
[29/Aug/2018:14:13:12 +0000] "PUT /eureka/apps/EUREKA-CLIENT1
[29/Aug/2018:14:13:13 +0000] "PUT /eureka/apps/EUREKA-CLIENT1           

試驗結果

終于到了看試驗結果的時候了。

每次心跳記憶體消耗＝12669.7 ÷ 316 ＝ 40.094KB。

雖說心跳是一次HTTP調用，但Eureka Client的調用還是有很多步驟。下面是一張debug中調用棧的截圖。

當然，心跳隻應用中非常小的一件事情，并不會給應用帶來什麼影響。 Eureka Client預設續租頻率為30秒/次，在實踐中根據需要調整即可，一般保持預設就行。

小結

以上純屬個人胡鬧，僅在自己的認知水準内做的嘗試性試驗，且隻做了一次試驗。試驗目的和試驗結果意義都不大，當中如有不對之處，還懇請指出。

當今時代，硬體資源早已不是瓶頸，經常是性能不夠，機器來湊，工作中遇到的問題更多的是業務開發所産生的BUG，寫好CRUD也不是件簡單的事情。不過多學點東西，擴充下視野總是好的。

歡迎關注陳同學的公衆号，一起學習，一起成長