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 | 25993.8(不变) |
| 20s后 | 31518.5 | 25993.8(不变) |
| 50s后 | 32738.6 | 25993.8(不变) |
| 104秒后 | 35174.1 | 26895.6 |
| 240秒后 | 41699.1 | 27797.1 |
| 316秒后 | 45056.0 | 27797.1 |
以上为在应用启动后约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也不是件简单的事情。不过多学点东西，扩展下视野总是好的。
欢迎关注陈同学的公众号，一起学习，一起成长
