文章目录
- 问题描述
- 问题分析
- 尝试优化业务代码
- 优化方案
- 修改后代码
- 补充点
问题描述
部门调整，接手一个新项目，为方便后续描述叫user-web，随后推动IT降本，要求根据实际业务量调整服务器实例数量和配置，调整前服务器配置为42实例x16核40g，降本方向主要为减少实例数和CPU数，参考的一个标准是近7日cpu的一个使用率调整到30%。调整前服务使用率为15%，通过几次调整后配置为4实例x8核12G，调整后在业务高峰期向外提供的rpc接口getUserInfo开始出现偶尔超时，该服务也只提供了一个rpc接口，中间随着服务器配置降低，接口超时数量开始稳定增多，后续增加到每天上百个，并且稳定出现，RT超过1s。
问题分析
引起接口超时原因有很多，正常getUserInfo接口调用时间都在5ms以内，rpc配置timeout是1s，峰值qps为60，首先这个问题每天都稳定出现，先排除网络抖动，最近又没有对项目做过任何代码修改，应该不是新引入的问题，唯一变化就是调整了服务器配置，考虑应该是资源不够用导致的。
观察服务运行时大盘，首先，观察最近30天整个服务的qps并没大的变化，发生超时的时间时业务高峰期，考虑是配置调整后资源过低，满足不了当前业务量。观察cpu使用率，峰值也在30%一下，应该不是cpu的影响，本身服务也确定不是计算密集型，符合认知，那就是可能是内存不够，内存不足，GC时STW单次时间过长或者频率过高，进而导致向外提供rpc超时，第一直觉是直接扩内存，直接翻倍，增加到16G，观察一天，依然有很多调用超时，并且对应超时时间短，内存占用率会有所波动，怀疑是有一些大对象，导致业务高峰期内存占用率过高，GC压力过大，GC的STW增加。
单台机器内存8G，堆内存占总内存3/4，8G，使用率在80%，堆外内存300M，代码中并没有使用堆外内存，应该不是堆外内存问题，堆内存也并没有持续升高，排除内存泄漏，进一步考虑是内存不够GC时STW单次时间过长或者GC频率过高引起的接口超时。
首先观察下使用的GC参数，使用的G1垃圾回收器，设置的最大停顿时间是200ms
下载gc日志，并筛选出GC时间比较长的日志，为了便于说明问题和正常服务gc日志进行了对比，：
超时接口提供方服务gc日志：
正常服务gc日志：
对比二者发现：
1、GC pause (G1 Evacuation Pause) (young)首先这是一次停顿应用程序（STOP）的年轻代垃圾回收，由to-space exhausted触发，回收后，Edgn 对象被清理从5252→0, 整个堆使用率显著降低，从 Heap: 8687.8M(9216.0M)->3048.5M(9216.0M)，这是一次有效的垃圾回收。
2、正常gc耗时10ms，异常gc耗时是700ms+，相差70倍使用多线程并行回收垃圾（Parallel time）和拷贝对象到目标区域空间不足触发Full GC（Evacuation Failure）时主要的两部分耗时，其中对象拷贝有事并行垃圾回收阶段最耗时部分，这表明有很多大的存活对象要进行拷贝，这些对象在业务高峰，并大量创建，导致空间不够用。
尝试优化业务代码
观察整个服务的运行大盘，发现在发生问题的同一时间段，有个接口耗时较高，然后接口调用日志链，最终发现了出问题的代码：
private LoadingCache<Integer, List<TVideo>> sortedShowVideoLoadingCache = Caffeine.newBuilder().expireAfterWrite(5, TimeUnit.MINUTES).maximumSize(1000)
.build(new CacheLoader<Integer, List<TVideo>>() {
@Override
public List<TVideo> load(@NonNull Integer albumId) throws Exception {
return myVideoProxy.getSortedShowVideosByAlbumId(albumId);
}
});
。。。
public List<TVideo> getShowVieosByAlbumId(int albumId) {
log.info("sortedShowVideoLoadingCache.size={}", sortedShowVideoLoadingCache.estimatedSize());
List<TVideo> videos = sortedShowVideoLoadingCache.get(albumId);
if (songs != null) {
return JsonUtils.readValue(JsonUtils.writeValue(videos), new TypeReference<List<TVideo>>() {
});// 问题语句
}
return videos;
}
问题语句分析：JsonUtils.readValue(JsonUtils.writeValue(videos), new TypeReference<List>() {});
问题1: 采集json序列化方式效率低，导致整个调用链路RT升高，和监控观察一一致，p99为2.5s；
问题2:创建了一遍多余对象，JsonUtils.writeValue(videos)创建了一个大的字符串，这个其实最后并没有返回，作为中间结果，依然占用了大量的空间，本省整个调用链路多次调用getShowVieosByAlbumId，创建的TVideo有一千多个，翻倍之后空间还是很可观的，同时由于使用序列化方式表抵销，导致在2.5s创建的这三个对象都无法释放。
优化方案
使用更高效序列化技术Hessian协议，将从rpc结果序列化为字节流，每次需要的时候，直接反序列化出来就是全新的对象。
修改后代码
private LoadingCache<Integer, List<TVideo>> sortedShowVideoLoadingCache = ConanCaffeineUtil.toSerializedLoadingCache(
Caffeine.newBuilder().expireAfterWrite(5, TimeUnit.MINUTES).maximumSize(1000)
.build(new CacheLoader<Integer, List<TVideo>>() {
@Override
public List<TVideo> load(@NonNull Integer albumId) throws Exception {
return myVideoProxy.getSortedShowVideosByAlbumId(albumId);
}
}));
public List<TVideo> getShowVieosByAlbumId(int albumId) {
return sortedAllSongLoadingCache.get(albumId);
}
优化后getShowVieosByAlbumId的RTp99下降到500ms，机器配置内存减少到8G，GC正常，没有再出现过超时。
补充点
1、其实刚开始是通过grafana对应监控大盘看接口调用时间，发现整个接口调用都是在50ms内，其实grafana统计是p99，本省超时接口数量又不多，所就看不到有长RT调用，最后通过报错日志trace调用链，观察每步调用时间。
2、中间调整了实例数、cpu核数和内存大小，cpu使用率过高会造成服务卡顿，内存不足，造成频繁gc和单次STW过长，都有可能引起提供接口超时，都需要考虑。
3、堆内存由jvm控制申请和释放，堆外内存操作系统使用，开发人员也可以手动申请堆外内存，但是不建议，容易因无忘记释放而造成内容泄漏。
4、G1的GC时间可控参数
5、G1的垃圾回收模式由几种，有什么区别？G1回收模型由Young GC、Mixed GC和Ful GC，
Young GC只回收年轻代区域（edgn，Survior）空间，仅年轻代空闲空间不足、老年代空间充足，Mixed GC除了回收年轻代，因为老年代因空间不够也需要回收，这两者都是小范围的，当复制空间不足（to-space exhausted），并多次尝试小范围回收空间依然不够时，可能会触发Ful GC，对整个堆的空间进行回收和整理，回收时间更长。
6、普通Young GC和由to-space exhausted引起的Young GC区别是，后者为了获得更多的空间，可能会执行多次额外的GC周期，停顿时间一般会大于设定的希望停顿时间。
7、G1垃圾回收器为什么将堆内存分为大小不同的块？一是提高收集的效率，多个回收线程在不同区域独立执行，二是根据需要灵活调整老年代和新生代的比例，三是更准确控制每次停顿的时间，根据历史垃圾回收记录，根据设置的最大停顿时间，使用预测模型，增量进行垃圾回收，四减少内存碎片化，每次收集之后，将对象移动到一个或者多个区域，留下来的都是大片连续可用的空间。
