问题描述
部门调整,接手一个新项目,为方便后续描述叫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垃圾回收器为什么将堆内存分为大小不同的块?一是提高收集的效率,多个回收线程在不同区域独立执行,二是根据需要灵活调整老年代和新生代的比例,三是更准确控制每次停顿的时间,根据历史垃圾回收记录,根据设置的最大停顿时间,使用预测模型,增量进行垃圾回收,四减少内存碎片化,每次收集之后,将对象移动到一个或者多个区域,留下来的都是大片连续可用的空间。